2025-12-01 02:53:15,301 - INFO - Domain Default found not creating
2025-12-01 02:53:15,518 - INFO - Project ctest-TestQos-38618290 not found, creating it
2025-12-01 02:53:16,073 - INFO - Created Project:ctest-TestQos-38618290, ID : fb6c960c-5cdf-461c-b559-a731ac8f9af7
2025-12-01 02:53:19,100 - DEBUG - Response for create_network : {'network': {'id': 'f22e1479-d4d6-40c8-9154-c89d84df00bd', 'name': 'ctest-vn-88240762', 'tenant_id': 'fb6c960c5cdf461cb559a731ac8f9af7', 'project_id': 'fb6c960c5cdf461cb559a731ac8f9af7', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': False, 'mtu': 0, 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestQos-38618290', 'ctest-vn-88240762'], 'port_security_enabled': True, 'description': ''}}
2025-12-01 02:53:19,411 - DEBUG - Response for create_subnet : {'subnet': {'id': '55924572-1ad7-436e-9d7c-896bbfdfc433', 'name': '', 'tenant_id': 'fb6c960c5cdf461cb559a731ac8f9af7', 'network_id': 'f22e1479-d4d6-40c8-9154-c89d84df00bd', 'ip_version': 4, 'cidr': '182.216.231.64/26', 'allocation_pools': [{'start': '182.216.231.66', 'end': '182.216.231.126'}], 'gateway_ip': '182.216.231.65', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '182.216.231.66', 'tags': [], 'project_id': 'fb6c960c5cdf461cb559a731ac8f9af7'}}
2025-12-01 02:53:19,635 - DEBUG - Response for create_subnet : {'subnet': {'id': '9f454f6d-5e48-4931-8423-114ffe655b9f', 'name': '', 'tenant_id': 'fb6c960c5cdf461cb559a731ac8f9af7', 'network_id': 'f22e1479-d4d6-40c8-9154-c89d84df00bd', 'ip_version': 6, 'cidr': '3354:92b:e45a:bea:2dc5:6a8::/96', 'allocation_pools': [{'start': '3354:92b:e45a:bea:2dc5:6a8:0:2', 'end': '3354:92b:e45a:bea:2dc5:6a8:ffff:fffe'}], 'gateway_ip': '3354:92b:e45a:bea:2dc5:6a8:0:1', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '3354:92b:e45a:bea:2dc5:6a8:0:2', 'tags': [], 'project_id': 'fb6c960c5cdf461cb559a731ac8f9af7'}}
2025-12-01 02:53:19,659 - INFO - Created VN ctest-vn-88240762
2025-12-01 02:53:19,672 - DEBUG - VN ctest-vn-88240762 UUID is f22e1479-d4d6-40c8-9154-c89d84df00bd
2025-12-01 02:53:20,124 - DEBUG - Response for create_network : {'network': {'id': '9bebbe1a-6e86-4d38-a462-cd210655a2b6', 'name': 'ctest-vn-07901685', 'tenant_id': 'fb6c960c5cdf461cb559a731ac8f9af7', 'project_id': 'fb6c960c5cdf461cb559a731ac8f9af7', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': False, 'mtu': 0, 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestQos-38618290', 'ctest-vn-07901685'], 'port_security_enabled': True, 'description': ''}}
2025-12-01 02:53:20,331 - DEBUG - Response for create_subnet : {'subnet': {'id': '724e5940-0628-45c3-8393-c6a10be85e00', 'name': '', 'tenant_id': 'fb6c960c5cdf461cb559a731ac8f9af7', 'network_id': '9bebbe1a-6e86-4d38-a462-cd210655a2b6', 'ip_version': 4, 'cidr': '153.99.195.128/26', 'allocation_pools': [{'start': '153.99.195.130', 'end': '153.99.195.190'}], 'gateway_ip': '153.99.195.129', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '153.99.195.130', 'tags': [], 'project_id': 'fb6c960c5cdf461cb559a731ac8f9af7'}}
2025-12-01 02:53:20,552 - DEBUG - Response for create_subnet : {'subnet': {'id': '71af51fe-2bc6-42e4-bee7-e146ead59163', 'name': '', 'tenant_id': 'fb6c960c5cdf461cb559a731ac8f9af7', 'network_id': '9bebbe1a-6e86-4d38-a462-cd210655a2b6', 'ip_version': 6, 'cidr': '3af2:f5da:64eb:e45f:ec68:3904::/96', 'allocation_pools': [{'start': '3af2:f5da:64eb:e45f:ec68:3904:0:2', 'end': '3af2:f5da:64eb:e45f:ec68:3904:ffff:fffe'}], 'gateway_ip': '3af2:f5da:64eb:e45f:ec68:3904:0:1', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '3af2:f5da:64eb:e45f:ec68:3904:0:2', 'tags': [], 'project_id': 'fb6c960c5cdf461cb559a731ac8f9af7'}}
2025-12-01 02:53:20,585 - INFO - Created VN ctest-vn-07901685
2025-12-01 02:53:20,600 - DEBUG - VN ctest-vn-07901685 UUID is 9bebbe1a-6e86-4d38-a462-cd210655a2b6
2025-12-01 02:53:20,788 - DEBUG - Services list from nova: [, , , ]
2025-12-01 02:53:21,960 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-4827-1), Zone: (nova:an-jenkins-deploy-platform-ansible-os-4827-1)
2025-12-01 02:53:23,558 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-4827-2), Zone: (nova:an-jenkins-deploy-platform-ansible-os-4827-2)
2025-12-01 02:53:25,144 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-4827-2), Zone: (nova:an-jenkins-deploy-platform-ansible-os-4827-2)
2025-12-01 02:53:25,144 - INFO - Waiting for VM ctest-TestQos-38618290-31387057 to be up..
2025-12-01 02:53:25,261 - DEBUG - VM is in ACTIVE state now
2025-12-01 02:53:25,261 - INFO - VM name : ctest-TestQos-38618290-31387057
2025-12-01 02:53:25,371 - DEBUG - VM ctest-TestQos-38618290-31387057 ID is a0f80735-6a09-4c86-acee-3bc1a7cb299d
2025-12-01 02:53:25,402 - DEBUG - VM ctest-TestQos-38618290-31387057 launched on Node an-jenkins-deploy-platform-ansible-os-4827-1
2025-12-01 02:53:25,520 - DEBUG - Requesting: http://10.0.0.23:8082/virtual-machine/a0f80735-6a09-4c86-acee-3bc1a7cb299d
2025-12-01 02:53:25,984 - DEBUG - Requesting: http://10.0.0.23:8082/virtual-machine/a0f80735-6a09-4c86-acee-3bc1a7cb299d
2025-12-01 02:53:26,053 - DEBUG - Requesting: http://10.0.0.23:8082/virtual-machine-interface/8563b02c-3b53-47d5-81dc-a0fce8f24387
2025-12-01 02:53:29,249 - 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-12-01 02:53:29,249 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-38618290-31387057 failed!
2025-12-01 02:53:29,267 - DEBUG - Gateway for vn default-domain:ctest-TestQos-38618290:ctest-vn-88240762 is 182.216.231.65 and allocation pool is NOT set
2025-12-01 02:53:29,267 - DEBUG - Gateway for vn default-domain:ctest-TestQos-38618290:ctest-vn-88240762 is 3354:92b:e45a:bea:2dc5:6a8:0:1 and allocation pool is NOT set
2025-12-01 02:53:33,347 - 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 1015ms')
2025-12-01 02:53:33,347 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-38618290-31387057 failed!
2025-12-01 02:53:33,363 - DEBUG - Gateway for vn default-domain:ctest-TestQos-38618290:ctest-vn-88240762 is 182.216.231.65 and allocation pool is NOT set
2025-12-01 02:53:33,363 - DEBUG - Gateway for vn default-domain:ctest-TestQos-38618290:ctest-vn-88240762 is 3354:92b:e45a:bea:2dc5:6a8:0:1 and allocation pool is NOT set
2025-12-01 02:53:37,440 - 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 1015ms')
2025-12-01 02:53:37,440 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-38618290-31387057 failed!
2025-12-01 02:53:37,459 - DEBUG - Gateway for vn default-domain:ctest-TestQos-38618290:ctest-vn-88240762 is 182.216.231.65 and allocation pool is NOT set
2025-12-01 02:53:37,460 - DEBUG - Gateway for vn default-domain:ctest-TestQos-38618290:ctest-vn-88240762 is 3354:92b:e45a:bea:2dc5:6a8:0:1 and allocation pool is NOT set
2025-12-01 02:53:41,534 - 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-12-01 02:53:41,534 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-38618290-31387057 failed!
2025-12-01 02:53:41,550 - DEBUG - Gateway for vn default-domain:ctest-TestQos-38618290:ctest-vn-88240762 is 182.216.231.65 and allocation pool is NOT set
2025-12-01 02:53:41,550 - DEBUG - Gateway for vn default-domain:ctest-TestQos-38618290:ctest-vn-88240762 is 3354:92b:e45a:bea:2dc5:6a8:0:1 and allocation pool is NOT set
2025-12-01 02:53:45,626 - 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')
2025-12-01 02:53:45,626 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-38618290-31387057 failed!
2025-12-01 02:53:45,642 - DEBUG - Gateway for vn default-domain:ctest-TestQos-38618290:ctest-vn-88240762 is 182.216.231.65 and allocation pool is NOT set
2025-12-01 02:53:45,642 - DEBUG - Gateway for vn default-domain:ctest-TestQos-38618290:ctest-vn-88240762 is 3354:92b:e45a:bea:2dc5:6a8:0:1 and allocation pool is NOT set
2025-12-01 02:53:49,732 - 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-12-01 02:53:49,732 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-38618290-31387057 failed!
2025-12-01 02:53:49,750 - DEBUG - Gateway for vn default-domain:ctest-TestQos-38618290:ctest-vn-88240762 is 182.216.231.65 and allocation pool is NOT set
2025-12-01 02:53:49,750 - DEBUG - Gateway for vn default-domain:ctest-TestQos-38618290:ctest-vn-88240762 is 3354:92b:e45a:bea:2dc5:6a8:0:1 and allocation pool is NOT set
2025-12-01 02:53:53,820 - 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 1008ms')
2025-12-01 02:53:53,820 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-38618290-31387057 failed!
2025-12-01 02:53:53,844 - DEBUG - Gateway for vn default-domain:ctest-TestQos-38618290:ctest-vn-88240762 is 182.216.231.65 and allocation pool is NOT set
2025-12-01 02:53:53,844 - DEBUG - Gateway for vn default-domain:ctest-TestQos-38618290:ctest-vn-88240762 is 3354:92b:e45a:bea:2dc5:6a8:0:1 and allocation pool is NOT set
2025-12-01 02:53:57,922 - 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')
2025-12-01 02:53:57,922 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-38618290-31387057 failed!
2025-12-01 02:53:57,941 - DEBUG - Gateway for vn default-domain:ctest-TestQos-38618290:ctest-vn-88240762 is 182.216.231.65 and allocation pool is NOT set
2025-12-01 02:53:57,941 - DEBUG - Gateway for vn default-domain:ctest-TestQos-38618290:ctest-vn-88240762 is 3354:92b:e45a:bea:2dc5:6a8:0:1 and allocation pool is NOT set
2025-12-01 02:54:02,015 - 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-12-01 02:54:02,016 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-38618290-31387057 failed!
2025-12-01 02:54:02,035 - DEBUG - Gateway for vn default-domain:ctest-TestQos-38618290:ctest-vn-88240762 is 182.216.231.65 and allocation pool is NOT set
2025-12-01 02:54:02,035 - DEBUG - Gateway for vn default-domain:ctest-TestQos-38618290:ctest-vn-88240762 is 3354:92b:e45a:bea:2dc5:6a8:0:1 and allocation pool is NOT set
2025-12-01 02:54:04,099 - 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=85.9 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=1.41 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.414/43.642/85.870/42.228 ms')
2025-12-01 02:54:04,100 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-38618290-31387057 passed
2025-12-01 02:54:04,177 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-12-01 02:54:04,177 - DEBUG - Waiting to SSH to VM ctest-TestQos-38618290-31387057, IP 182.216.231.67, Port 22
2025-12-01 02:54:04,247 - 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-12-01 02:54:04,359 - DEBUG - VM ctest-TestQos-38618290-31387057 is NOT ready for SSH connections, VM status: ACTIVE
2025-12-01 02:54:09,359 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-12-01 02:54:09,360 - DEBUG - Waiting to SSH to VM ctest-TestQos-38618290-31387057, IP 182.216.231.67, Port 22
2025-12-01 02:54:09,429 - 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-12-01 02:54:09,525 - DEBUG - VM ctest-TestQos-38618290-31387057 is NOT ready for SSH connections, VM status: ACTIVE
2025-12-01 02:54:14,525 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-12-01 02:54:14,525 - DEBUG - Waiting to SSH to VM ctest-TestQos-38618290-31387057, IP 182.216.231.67, Port 22
2025-12-01 02:54:14,580 - 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-12-01 02:54:14,678 - DEBUG - VM ctest-TestQos-38618290-31387057 is NOT ready for SSH connections, VM status: ACTIVE
2025-12-01 02:54:19,679 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-12-01 02:54:19,680 - DEBUG - Waiting to SSH to VM ctest-TestQos-38618290-31387057, IP 182.216.231.67, Port 22
2025-12-01 02:54:19,747 - 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-12-01 02:54:19,864 - DEBUG - VM ctest-TestQos-38618290-31387057 is NOT ready for SSH connections, VM status: ACTIVE
2025-12-01 02:54:24,865 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-12-01 02:54:24,865 - DEBUG - Waiting to SSH to VM ctest-TestQos-38618290-31387057, IP 182.216.231.67, Port 22
2025-12-01 02:54:24,921 - 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-12-01 02:54:25,024 - DEBUG - VM ctest-TestQos-38618290-31387057 is NOT ready for SSH connections, VM status: ACTIVE
2025-12-01 02:54:30,025 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-12-01 02:54:30,025 - DEBUG - Waiting to SSH to VM ctest-TestQos-38618290-31387057, IP 182.216.231.67, Port 22
2025-12-01 02:54:30,196 - DEBUG - VM ctest-TestQos-38618290-31387057 is ready for SSH connections
2025-12-01 02:54:30,196 - INFO - Waiting for VM ctest-TestQos-38618290-93699033 to be up..
2025-12-01 02:54:30,288 - DEBUG - VM is in ACTIVE state now
2025-12-01 02:54:30,288 - INFO - VM name : ctest-TestQos-38618290-93699033
2025-12-01 02:54:30,379 - DEBUG - VM ctest-TestQos-38618290-93699033 ID is 4ee0c256-6fd4-4f9d-8c2b-981883474266
2025-12-01 02:54:30,379 - DEBUG - VM ctest-TestQos-38618290-93699033 launched on Node an-jenkins-deploy-platform-ansible-os-4827-2
2025-12-01 02:54:30,466 - DEBUG - Requesting: http://10.0.0.23:8082/virtual-machine/4ee0c256-6fd4-4f9d-8c2b-981883474266
2025-12-01 02:54:30,480 - DEBUG - Requesting: http://10.0.0.23:8082/virtual-machine-interface/e0ca2506-a231-4aaf-956e-f24aff338786
2025-12-01 02:54:31,666 - 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.37 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=2.53 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 = 2.525/2.946/3.368/0.421 ms')
2025-12-01 02:54:31,666 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-38618290-93699033 passed
2025-12-01 02:54:31,738 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-12-01 02:54:31,738 - DEBUG - Waiting to SSH to VM ctest-TestQos-38618290-93699033, IP 182.216.231.68, Port 22
2025-12-01 02:54:31,805 - 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-12-01 02:54:31,915 - DEBUG - VM ctest-TestQos-38618290-93699033 is NOT ready for SSH connections, VM status: ACTIVE
2025-12-01 02:54:36,916 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-12-01 02:54:36,916 - DEBUG - Waiting to SSH to VM ctest-TestQos-38618290-93699033, IP 182.216.231.68, Port 22
2025-12-01 02:54:36,985 - 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-12-01 02:54:37,129 - DEBUG - VM ctest-TestQos-38618290-93699033 is NOT ready for SSH connections, VM status: ACTIVE
2025-12-01 02:54:42,130 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-12-01 02:54:42,130 - DEBUG - Waiting to SSH to VM ctest-TestQos-38618290-93699033, IP 182.216.231.68, Port 22
2025-12-01 02:54:42,297 - DEBUG - VM ctest-TestQos-38618290-93699033 is ready for SSH connections
2025-12-01 02:54:42,297 - INFO - Waiting for VM ctest-TestQos-38618290-57170245 to be up..
2025-12-01 02:54:42,404 - DEBUG - VM is in ACTIVE state now
2025-12-01 02:54:42,404 - INFO - VM name : ctest-TestQos-38618290-57170245
2025-12-01 02:54:42,527 - DEBUG - VM ctest-TestQos-38618290-57170245 ID is 36a58537-54b1-466b-8dc0-51eb406b5471
2025-12-01 02:54:42,527 - DEBUG - VM ctest-TestQos-38618290-57170245 launched on Node an-jenkins-deploy-platform-ansible-os-4827-2
2025-12-01 02:54:42,613 - DEBUG - Requesting: http://10.0.0.23:8082/virtual-machine/36a58537-54b1-466b-8dc0-51eb406b5471
2025-12-01 02:54:42,627 - DEBUG - Requesting: http://10.0.0.23:8082/virtual-machine-interface/8c233cbb-82f0-4d6e-9adb-e5b3f10abaea
2025-12-01 02:54:43,795 - 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=4.57 ms\r\n64 bytes from 169.254.0.4: icmp_seq=2 ttl=63 time=0.359 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.359/2.462/4.565/2.103 ms')
2025-12-01 02:54:43,795 - INFO - Ping to Metadata IP 169.254.0.4 of VM ctest-TestQos-38618290-57170245 passed
2025-12-01 02:54:43,881 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-12-01 02:54:43,881 - DEBUG - Waiting to SSH to VM ctest-TestQos-38618290-57170245, IP 153.99.195.131, Port 22
2025-12-01 02:54:44,049 - DEBUG - VM ctest-TestQos-38618290-57170245 is ready for SSH connections
2025-12-01 02:54:44,054 - INFO - ================================================================================
2025-12-01 02:54:44,055 - INFO - STARTING TEST : test_qos_remark_dscp_on_vmi
2025-12-01 02:54:44,055 - 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-12-01 02:54:45,379 - DEBUG - Nothing to compare xmpp stats {'10.0.0.22': {'10.20.0.209': '0', '10.20.0.192': '0'}, '10.0.0.241': {'10.20.0.209': '0', '10.20.0.192': '0'}} with
2025-12-01 02:54:45,380 - INFO - Initial checks done. Running the testcase now
2025-12-01 02:54:45,380 - INFO -
2025-12-01 02:54:45,388 - DEBUG - FC Dict is {'fc_id': 0, 'dscp': 10, 'dot1p': 1, 'exp': 1, 'connections': }
2025-12-01 02:54:45,674 - INFO - Created FC ['default-global-system-config', 'default-global-qos-config', 'ctest-fc-90128107'], UUID 94420b4a-244d-4862-9519-c7a1c9f387a0
2025-12-01 02:54:46,058 - INFO - Created QosConfig ['default-domain', 'ctest-TestQos-38618290', 'ctest-qos_config-38170498'], UUID: 5f8fa1a4-2ea0-40d7-86a5-ca053491031a
2025-12-01 02:54:46,110 - INFO - Applying qos-config on VM 8563b02c-3b53-47d5-81dc-a0fce8f24387
2025-12-01 02:54:46,380 - DEBUG - VM is in ACTIVE state now
2025-12-01 02:54:46,650 - DEBUG - Requesting: http://10.0.0.23:8082/virtual-machine/a0f80735-6a09-4c86-acee-3bc1a7cb299d
2025-12-01 02:54:46,659 - DEBUG - Requesting: http://10.0.0.23:8082/virtual-machine-interface/8563b02c-3b53-47d5-81dc-a0fce8f24387
2025-12-01 02:54:46,671 - DEBUG - Requesting: http://10.0.0.23:8082/instance-ip/32fa1c85-ca15-4064-ac20-39d0cee53cc7
2025-12-01 02:54:46,682 - DEBUG - Requesting: http://10.0.0.23:8082/instance-ip/5d32fbb1-d37f-4263-99e4-1a9e9bbf2b84
2025-12-01 02:54:46,902 - DEBUG - VM is in ACTIVE state now
2025-12-01 02:54:47,201 - DEBUG - Requesting: http://10.0.0.23:8082/virtual-machine/4ee0c256-6fd4-4f9d-8c2b-981883474266
2025-12-01 02:54:47,211 - DEBUG - Requesting: http://10.0.0.23:8082/virtual-machine-interface/e0ca2506-a231-4aaf-956e-f24aff338786
2025-12-01 02:54:47,223 - DEBUG - Requesting: http://10.0.0.23:8082/instance-ip/9b897ee6-9df0-4d46-b412-5845118f5a55
2025-12-01 02:54:47,240 - DEBUG - Requesting: http://10.0.0.23:8082/instance-ip/c93af804-e4c5-4775-a213-7033bce3c9f3
2025-12-01 02:54:47,286 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-12-01 02:54:47,286 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-12-01 02:54:47,286 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-12-01 02:54:47,287 - INFO - Starting hping3 on ctest-TestQos-38618290-31387057, args: --destport 20000 --baseport 10000 --count 20000 --interval 1 --udp --tos 4 --keep --numeric
2025-12-01 02:54:47,287 - DEBUG - Hping3 cmd : hping3 --destport 20000 --baseport 10000 --count 20000 --interval 1 --udp --tos 4 --keep --numeric 182.216.231.68 1>/tmp/hping_ctest-random-82969114.log 2>/tmp/hping_ctest-random-82969114.result
2025-12-01 02:54:47,287 - DEBUG - Running remote_cmd, Cmd : hping3 --destport 20000 --baseport 10000 --count 20000 --interval 1 --udp --tos 4 --keep --numeric 182.216.231.68 1>/tmp/hping_ctest-random-82969114.log 2>/tmp/hping_ctest-random-82969114.result, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.22, gateway password: c0ntrail123
2025-12-01 02:54:47,288 - DEBUG - nohup hping3 --destport 20000 --baseport 10000 --count 20000 --interval 1 --udp --tos 4 --keep --numeric 182.216.231.68 1>/tmp/hping_ctest-random-82969114.log 2>/tmp/hping_ctest-random-82969114.result & echo $! > /tmp/hping_ctest-random-82969114.pid
2025-12-01 02:54:55,072 - DEBUG - None
2025-12-01 02:55:00,296 - DEBUG - Forward flow: {'index': '380096', 'rflow': '197928', 'sip': '182.216.231.67', 'sport': '10000', 'dip': '182.216.231.68', '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': '51781', 'ttl': '0', 'qos_id': '0', 'gen_id': '1', 'tcp_seq': '0', 'oflow_bytes': '0', 'oflow_packets': '0', 'underlay_gw_index': '-1'}
2025-12-01 02:55:00,298 - DEBUG - Reverse flow: {'index': '197928', 'rflow': '380096', 'sip': '182.216.231.68', 'sport': '20000', 'dip': '182.216.231.67', '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': '52454', 'ttl': '0', 'qos_id': '0', 'gen_id': '1', 'tcp_seq': '0', 'oflow_bytes': '0', 'oflow_packets': '0', 'underlay_gw_index': '-1'}
2025-12-01 02:55:00,298 - DEBUG - The filter pattern is ['udp', 'and', 'src port 51781']
2025-12-01 02:55:00,298 - DEBUG - The filter string is '(udp and src port 51781)'
2025-12-01 02:55:00,380 - DEBUG - Executing command: sudo tcpdump -nni ens6 -U -vvxx '(udp and src port 51781)' -w /tmp/ens6_ctest-random-29151424.pcap
2025-12-01 02:55:05,480 - DEBUG - Executing command: sudo kill $(ps -ef|grep tcpdump | grep pcap| awk '{print $2}')
2025-12-01 02:55:07,484 - DEBUG - Ensuring hping3 instance with result file /tmp/hping_ctest-random-82969114.result on ctest-TestQos-38618290-31387057 is stopped
2025-12-01 02:55:07,484 - DEBUG - Running remote_cmd, Cmd : cat /tmp/hping_ctest-random-82969114.pid | xargs kill , host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.22, gateway password: c0ntrail123
2025-12-01 02:55:07,484 - DEBUG - cat /tmp/hping_ctest-random-82969114.pid | xargs kill
2025-12-01 02:55:08,258 - DEBUG - None
2025-12-01 02:55:08,258 - DEBUG - Running remote_cmd, Cmd : cat /tmp/hping_ctest-random-82969114.result, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.22, gateway password: c0ntrail123
2025-12-01 02:55:08,258 - DEBUG - cat /tmp/hping_ctest-random-82969114.result
2025-12-01 02:55:08,584 - DEBUG - --- 182.216.231.68 hping statistic ---
14 packets transmitted, 14 packets received, 0% packet loss
round-trip min/avg/max = 12.7/6512.8/13015.9 ms
2025-12-01 02:55:08,584 - DEBUG - Running remote_cmd, Cmd : cat /tmp/hping_ctest-random-82969114.log, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.22, gateway password: c0ntrail123
2025-12-01 02:55:08,584 - DEBUG - cat /tmp/hping_ctest-random-82969114.log
2025-12-01 02:55:08,936 - DEBUG - HPING 182.216.231.68 (eth0 182.216.231.68): udp mode set, 28 headers + 0 data bytes
ICMP Port Unreachable from ip=182.216.231.68
status=0 port=10000 seq=0
ICMP Port Unreachable from ip=182.216.231.68
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=182.216.231.68
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=182.216.231.68
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=182.216.231.68
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=182.216.231.68
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=182.216.231.68
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=182.216.231.68
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=182.216.231.68
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=182.216.231.68
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=182.216.231.68
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=182.216.231.68
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=182.216.231.68
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=182.216.231.68
status=1 port=10000 seq=0
2025-12-01 02:55:08,937 - DEBUG - Hping3 stats: {'sent': '14', 'received': '14', 'loss': '0', 'rtt_min': '12.7', 'rtt_avg': '6512.8', 'rtt_max': '13015.9'}
2025-12-01 02:55:08,937 - DEBUG - Executing command: sudo tcpdump -nnr /tmp/ens6_ctest-random-29151424.pcap | wc -l
2025-12-01 02:55:08,953 - DEBUG - STDOUT: 16
2025-12-01 02:55:08,953 - DEBUG - STDERR: reading from file /tmp/ens6_ctest-random-29151424.pcap, link-type EN10MB (Ethernet), snapshot length 262144
2025-12-01 02:55:08,953 - DEBUG - 16 packets are found in tcpdump output file /tmp/ens6_ctest-random-29151424.pcap but expected 1, which is fine
2025-12-01 02:55:08,953 - INFO - 16 packets are found in tcpdump output as expected
2025-12-01 02:55:08,954 - DEBUG - Executing command: sudo kill $(ps -ef|grep tcpdump | grep pcap| awk '{print $2}')
2025-12-01 02:55:11,016 - DEBUG - ['/contrail-test/ens6_ctest-random-29151424.pcap']
2025-12-01 02:55:11,017 - DEBUG - Verifying for packet number 0
2025-12-01 02:55:11,017 - DEBUG - Validated DSCP marking of 10
2025-12-01 02:55:11,017 - DEBUG - Verifying for packet number 1
2025-12-01 02:55:11,017 - DEBUG - Validated DSCP marking of 10
2025-12-01 02:55:11,017 - DEBUG - Verifying for packet number 2
2025-12-01 02:55:11,017 - DEBUG - Validated DSCP marking of 10
2025-12-01 02:55:11,017 - DEBUG - Verifying for packet number 3
2025-12-01 02:55:11,017 - DEBUG - Validated DSCP marking of 10
2025-12-01 02:55:11,017 - INFO - Packet QoS marking validation passed
2025-12-01 02:55:11,017 - DEBUG - Executing command: sudo tcpdump -nnr /tmp/ens6_ctest-random-29151424.pcap | wc -l
2025-12-01 02:55:11,031 - DEBUG - STDOUT: 16
2025-12-01 02:55:11,031 - DEBUG - STDERR: reading from file /tmp/ens6_ctest-random-29151424.pcap, link-type EN10MB (Ethernet), snapshot length 262144
2025-12-01 02:55:11,032 - DEBUG - 16 packets are found in tcpdump output file /tmp/ens6_ctest-random-29151424.pcap but expected 1, which is fine
2025-12-01 02:55:11,032 - INFO - 16 packets are found in tcpdump output as expected
2025-12-01 02:55:11,032 - DEBUG - Executing command: sudo kill $(ps -ef|grep tcpdump | grep pcap| awk '{print $2}')
2025-12-01 02:55:13,090 - DEBUG - ['/contrail-test/ens6_ctest-random-29151424.pcap']
2025-12-01 02:55:13,091 - DEBUG - Verifying for packet number 0
2025-12-01 02:55:13,091 - DEBUG - Interface ens6 does not seem to be a tagged intf. Skipping dot1p check
2025-12-01 02:55:13,091 - DEBUG - Verifying for packet number 1
2025-12-01 02:55:13,091 - DEBUG - Interface ens6 does not seem to be a tagged intf. Skipping dot1p check
2025-12-01 02:55:13,091 - DEBUG - Verifying for packet number 2
2025-12-01 02:55:13,091 - DEBUG - Interface ens6 does not seem to be a tagged intf. Skipping dot1p check
2025-12-01 02:55:13,091 - DEBUG - Verifying for packet number 3
2025-12-01 02:55:13,091 - DEBUG - Interface ens6 does not seem to be a tagged intf. Skipping dot1p check
2025-12-01 02:55:13,091 - INFO - Packet QoS marking validation passed
2025-12-01 02:55:13,199 - INFO - Removing qos-config on VM 8563b02c-3b53-47d5-81dc-a0fce8f24387
2025-12-01 02:55:13,273 - INFO - Deleting Qos config ['default-domain', 'ctest-TestQos-38618290', 'ctest-qos_config-38170498'], UUID: 5f8fa1a4-2ea0-40d7-86a5-ca053491031a
2025-12-01 02:55:13,362 - INFO - Deleting FC ['default-global-system-config', 'default-global-qos-config', 'ctest-fc-90128107'], UUID: 94420b4a-244d-4862-9519-c7a1c9f387a0
2025-12-01 02:55:14,716 - DEBUG - No XMPP flaps were noticed during the test
2025-12-01 02:55:14,716 - INFO - --------------------------------------------------------------------------------
2025-12-01 02:55:14,719 - INFO - Deleting VM ctest-TestQos-38618290-57170245
2025-12-01 02:55:14,804 - INFO - Deleting VM ctest-TestQos-38618290-93699033
2025-12-01 02:55:14,880 - INFO - Deleting VM ctest-TestQos-38618290-31387057
2025-12-01 02:55:14,980 - INFO - Deleting VN ctest-vn-07901685
2025-12-01 02:55:15,033 - DEBUG - VN 9bebbe1a-6e86-4d38-a462-cd210655a2b6 still in use: Unable to complete operation on network 9bebbe1a-6e86-4d38-a462-cd210655a2b6. There are one or more ports still in use on the network.
Neutron server returns request_ids: ['req-f8cd1143-2dd0-4690-8721-4399088a69be']
2025-12-01 02:55:15,033 - WARNING - Deleting VN ctest-vn-07901685 failed..Will retry
2025-12-01 02:55:17,224 - DEBUG - Response for deleting network ()
2025-12-01 02:55:17,225 - INFO - Deleting VN ctest-vn-88240762
2025-12-01 02:55:17,462 - DEBUG - Response for deleting network ()
2025-12-01 02:55:18,328 - INFO - Deleted project: ctest-TestQos-38618290, ID : fb6c960c-5cdf-461c-b559-a731ac8f9af7