2026-09-07 03:14:01,674 - INFO - Domain Default found not creating
2026-09-07 03:14:01,867 - INFO - Project ctest-TestQos-61375844 not found, creating it
2026-09-07 03:14:02,412 - INFO - Created Project:ctest-TestQos-61375844, ID : 6b0df0b8-ab07-4a93-a949-f97c3e6ef45d
2026-09-07 03:14:05,268 - DEBUG - Response for create_network : {'network': {'id': 'd26266a0-b2fc-459c-881e-7b0178acf014', 'name': 'ctest-vn-58401712', 'tenant_id': '6b0df0b8ab074a93a949f97c3e6ef45d', 'project_id': '6b0df0b8ab074a93a949f97c3e6ef45d', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': False, 'mtu': 0, 'tags': [], 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestQos-61375844', 'ctest-vn-58401712'], 'port_security_enabled': True, 'description': ''}}
2026-09-07 03:14:05,563 - DEBUG - Response for create_subnet : {'subnet': {'id': 'a4104d35-8baf-4eff-bfd4-1af133ea2ee8', 'name': '', 'tenant_id': '6b0df0b8ab074a93a949f97c3e6ef45d', 'network_id': 'd26266a0-b2fc-459c-881e-7b0178acf014', 'ip_version': 4, 'cidr': '23.150.121.192/26', 'allocation_pools': [{'start': '23.150.121.194', 'end': '23.150.121.254'}], 'gateway_ip': '23.150.121.193', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '23.150.121.194', 'tags': [], 'project_id': '6b0df0b8ab074a93a949f97c3e6ef45d'}}
2026-09-07 03:14:05,805 - DEBUG - Response for create_subnet : {'subnet': {'id': '7d163f4a-1577-4898-a509-5fbb824a4649', 'name': '', 'tenant_id': '6b0df0b8ab074a93a949f97c3e6ef45d', 'network_id': 'd26266a0-b2fc-459c-881e-7b0178acf014', 'ip_version': 6, 'cidr': '2a1f:9726:870d:549b:d0a1:ea73::/96', 'allocation_pools': [{'start': '2a1f:9726:870d:549b:d0a1:ea73:0:2', 'end': '2a1f:9726:870d:549b:d0a1:ea73:ffff:fffe'}], 'gateway_ip': '2a1f:9726:870d:549b:d0a1:ea73:0:1', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '2a1f:9726:870d:549b:d0a1:ea73:0:2', 'tags': [], 'project_id': '6b0df0b8ab074a93a949f97c3e6ef45d'}}
2026-09-07 03:14:05,839 - INFO - Created VN ctest-vn-58401712
2026-09-07 03:14:05,853 - DEBUG - VN ctest-vn-58401712 UUID is d26266a0-b2fc-459c-881e-7b0178acf014
2026-09-07 03:14:06,280 - DEBUG - Response for create_network : {'network': {'id': 'd6640534-2e1a-4c14-bfb9-c0115574d86e', 'name': 'ctest-vn-93631710', 'tenant_id': '6b0df0b8ab074a93a949f97c3e6ef45d', 'project_id': '6b0df0b8ab074a93a949f97c3e6ef45d', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': False, 'mtu': 0, 'tags': [], 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestQos-61375844', 'ctest-vn-93631710'], 'port_security_enabled': True, 'description': ''}}
2026-09-07 03:14:06,512 - DEBUG - Response for create_subnet : {'subnet': {'id': '7a33c417-2d32-4a42-8143-52bd94c778dc', 'name': '', 'tenant_id': '6b0df0b8ab074a93a949f97c3e6ef45d', 'network_id': 'd6640534-2e1a-4c14-bfb9-c0115574d86e', 'ip_version': 4, 'cidr': '34.154.149.0/26', 'allocation_pools': [{'start': '34.154.149.2', 'end': '34.154.149.62'}], 'gateway_ip': '34.154.149.1', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '34.154.149.2', 'tags': [], 'project_id': '6b0df0b8ab074a93a949f97c3e6ef45d'}}
2026-09-07 03:14:06,770 - DEBUG - Response for create_subnet : {'subnet': {'id': '0366eed9-43c7-4726-84e5-44b98d2448fc', 'name': '', 'tenant_id': '6b0df0b8ab074a93a949f97c3e6ef45d', 'network_id': 'd6640534-2e1a-4c14-bfb9-c0115574d86e', 'ip_version': 6, 'cidr': '2f2f:3c20:c0f5:695e:ace2:4ae1::/96', 'allocation_pools': [{'start': '2f2f:3c20:c0f5:695e:ace2:4ae1:0:2', 'end': '2f2f:3c20:c0f5:695e:ace2:4ae1:ffff:fffe'}], 'gateway_ip': '2f2f:3c20:c0f5:695e:ace2:4ae1:0:1', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '2f2f:3c20:c0f5:695e:ace2:4ae1:0:2', 'tags': [], 'project_id': '6b0df0b8ab074a93a949f97c3e6ef45d'}}
2026-09-07 03:14:06,806 - INFO - Created VN ctest-vn-93631710
2026-09-07 03:14:06,818 - DEBUG - VN ctest-vn-93631710 UUID is d6640534-2e1a-4c14-bfb9-c0115574d86e
2026-09-07 03:14:06,988 - DEBUG - Services list from nova: [, , , ]
2026-09-07 03:14:07,571 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-6258-1), Zone: (nova:an-jenkins-deploy-platform-ansible-os-6258-1)
2026-09-07 03:14:08,187 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-6258-2), Zone: (nova:an-jenkins-deploy-platform-ansible-os-6258-2)
2026-09-07 03:14:08,824 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-6258-2), Zone: (nova:an-jenkins-deploy-platform-ansible-os-6258-2)
2026-09-07 03:14:08,824 - INFO - Waiting for VM ctest-TestQos-61375844-42042589 to be up..
2026-09-07 03:14:08,876 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2026-09-07 03:14:13,986 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2026-09-07 03:14:19,080 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2026-09-07 03:14:24,174 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2026-09-07 03:14:29,282 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2026-09-07 03:14:34,381 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2026-09-07 03:14:39,562 - DEBUG - VM is in ACTIVE state now
2026-09-07 03:14:39,563 - INFO - VM name : ctest-TestQos-61375844-42042589
2026-09-07 03:14:39,726 - DEBUG - VM ctest-TestQos-61375844-42042589 ID is b46eae48-e65f-42da-9d00-54d67b7334d2
2026-09-07 03:14:39,761 - DEBUG - VM ctest-TestQos-61375844-42042589 launched on Node an-jenkins-deploy-platform-ansible-os-6258-1
2026-09-07 03:14:39,863 - DEBUG - Requesting: http://10.0.0.186:8082/virtual-machine/b46eae48-e65f-42da-9d00-54d67b7334d2
2026-09-07 03:14:40,254 - DEBUG - Requesting: http://10.0.0.186:8082/virtual-machine/b46eae48-e65f-42da-9d00-54d67b7334d2
2026-09-07 03:14:40,292 - DEBUG - Requesting: http://10.0.0.186:8082/virtual-machine-interface/21a98b9c-bce5-4f23-8d8f-b5307ebeb69c
2026-09-07 03:14:43,494 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 0 received, 100% packet loss, time 1022ms')
2026-09-07 03:14:43,495 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-61375844-42042589 failed!
2026-09-07 03:14:43,510 - DEBUG - Gateway for vn default-domain:ctest-TestQos-61375844:ctest-vn-58401712 is 23.150.121.193 and allocation pool is NOT set
2026-09-07 03:14:43,510 - DEBUG - Gateway for vn default-domain:ctest-TestQos-61375844:ctest-vn-58401712 is 2a1f:9726:870d:549b:d0a1:ea73:0:1 and allocation pool is NOT set
2026-09-07 03:14:47,590 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 0 received, 100% packet loss, time 1009ms')
2026-09-07 03:14:47,590 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-61375844-42042589 failed!
2026-09-07 03:14:47,606 - DEBUG - Gateway for vn default-domain:ctest-TestQos-61375844:ctest-vn-58401712 is 23.150.121.193 and allocation pool is NOT set
2026-09-07 03:14:47,606 - DEBUG - Gateway for vn default-domain:ctest-TestQos-61375844:ctest-vn-58401712 is 2a1f:9726:870d:549b:d0a1:ea73:0:1 and allocation pool is NOT set
2026-09-07 03:14:51,684 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 0 received, 100% packet loss, time 1011ms')
2026-09-07 03:14:51,684 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-61375844-42042589 failed!
2026-09-07 03:14:51,699 - DEBUG - Gateway for vn default-domain:ctest-TestQos-61375844:ctest-vn-58401712 is 23.150.121.193 and allocation pool is NOT set
2026-09-07 03:14:51,700 - DEBUG - Gateway for vn default-domain:ctest-TestQos-61375844:ctest-vn-58401712 is 2a1f:9726:870d:549b:d0a1:ea73:0:1 and allocation pool is NOT set
2026-09-07 03:14:55,781 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 0 received, 100% packet loss, time 1017ms')
2026-09-07 03:14:55,781 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-61375844-42042589 failed!
2026-09-07 03:14:55,804 - DEBUG - Gateway for vn default-domain:ctest-TestQos-61375844:ctest-vn-58401712 is 23.150.121.193 and allocation pool is NOT set
2026-09-07 03:14:55,805 - DEBUG - Gateway for vn default-domain:ctest-TestQos-61375844:ctest-vn-58401712 is 2a1f:9726:870d:549b:d0a1:ea73:0:1 and allocation pool is NOT set
2026-09-07 03:14:59,877 - 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')
2026-09-07 03:14:59,877 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-61375844-42042589 failed!
2026-09-07 03:14:59,893 - DEBUG - Gateway for vn default-domain:ctest-TestQos-61375844:ctest-vn-58401712 is 23.150.121.193 and allocation pool is NOT set
2026-09-07 03:14:59,894 - DEBUG - Gateway for vn default-domain:ctest-TestQos-61375844:ctest-vn-58401712 is 2a1f:9726:870d:549b:d0a1:ea73:0:1 and allocation pool is NOT set
2026-09-07 03:15:03,971 - 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')
2026-09-07 03:15:03,971 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-61375844-42042589 failed!
2026-09-07 03:15:03,989 - DEBUG - Gateway for vn default-domain:ctest-TestQos-61375844:ctest-vn-58401712 is 23.150.121.193 and allocation pool is NOT set
2026-09-07 03:15:03,989 - DEBUG - Gateway for vn default-domain:ctest-TestQos-61375844:ctest-vn-58401712 is 2a1f:9726:870d:549b:d0a1:ea73:0:1 and allocation pool is NOT set
2026-09-07 03:15:06,053 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n64 bytes from 169.254.0.3: icmp_seq=1 ttl=63 time=10.6 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=0.993 ms\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 2 received, 0% packet loss, time 1002ms\r\nrtt min/avg/max/mdev = 0.993/5.809/10.625/4.816 ms')
2026-09-07 03:15:06,054 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-61375844-42042589 passed
2026-09-07 03:15:06,127 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-09-07 03:15:06,127 - DEBUG - Waiting to SSH to VM ctest-TestQos-61375844-42042589, IP 23.150.121.195, Port 22
2026-09-07 03:15:06,207 - DEBUG - Error on ssh to ubuntu@169.254.0.3:22, result: /bin/bash: connect: Connection refused
/bin/bash: line 1: /dev/tcp/169.254.0.3/22: Connection refused {'failed': True, 'command': '(echo > /dev/tcp/169.254.0.3/22)', 'real_command': '/bin/bash -l -c "(echo > /dev/tcp/169.254.0.3/22)"', 'return_code': 1, 'succeeded': False, 'stderr': ''}
2026-09-07 03:15:06,339 - DEBUG - VM ctest-TestQos-61375844-42042589 is NOT ready for SSH connections, VM status: ACTIVE
2026-09-07 03:15:11,340 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-09-07 03:15:11,340 - DEBUG - Waiting to SSH to VM ctest-TestQos-61375844-42042589, IP 23.150.121.195, Port 22
2026-09-07 03:15:11,408 - DEBUG - Error on ssh to ubuntu@169.254.0.3:22, result: /bin/bash: connect: Connection refused
/bin/bash: line 1: /dev/tcp/169.254.0.3/22: Connection refused {'failed': True, 'command': '(echo > /dev/tcp/169.254.0.3/22)', 'real_command': '/bin/bash -l -c "(echo > /dev/tcp/169.254.0.3/22)"', 'return_code': 1, 'succeeded': False, 'stderr': ''}
2026-09-07 03:15:11,498 - DEBUG - VM ctest-TestQos-61375844-42042589 is NOT ready for SSH connections, VM status: ACTIVE
2026-09-07 03:15:16,499 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-09-07 03:15:16,499 - DEBUG - Waiting to SSH to VM ctest-TestQos-61375844-42042589, IP 23.150.121.195, Port 22
2026-09-07 03:15:16,569 - DEBUG - Error on ssh to ubuntu@169.254.0.3:22, result: /bin/bash: connect: Connection refused
/bin/bash: line 1: /dev/tcp/169.254.0.3/22: Connection refused {'failed': True, 'command': '(echo > /dev/tcp/169.254.0.3/22)', 'real_command': '/bin/bash -l -c "(echo > /dev/tcp/169.254.0.3/22)"', 'return_code': 1, 'succeeded': False, 'stderr': ''}
2026-09-07 03:15:16,687 - DEBUG - VM ctest-TestQos-61375844-42042589 is NOT ready for SSH connections, VM status: ACTIVE
2026-09-07 03:15:21,688 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-09-07 03:15:21,688 - DEBUG - Waiting to SSH to VM ctest-TestQos-61375844-42042589, IP 23.150.121.195, Port 22
2026-09-07 03:15:21,864 - DEBUG - VM ctest-TestQos-61375844-42042589 is ready for SSH connections
2026-09-07 03:15:21,864 - INFO - Waiting for VM ctest-TestQos-61375844-27031052 to be up..
2026-09-07 03:15:21,956 - DEBUG - VM is in ACTIVE state now
2026-09-07 03:15:21,956 - INFO - VM name : ctest-TestQos-61375844-27031052
2026-09-07 03:15:22,055 - DEBUG - VM ctest-TestQos-61375844-27031052 ID is 2f7e3aa7-a9c1-480a-ac86-ed9d13993d23
2026-09-07 03:15:22,055 - DEBUG - VM ctest-TestQos-61375844-27031052 launched on Node an-jenkins-deploy-platform-ansible-os-6258-2
2026-09-07 03:15:22,152 - DEBUG - Requesting: http://10.0.0.186:8082/virtual-machine/2f7e3aa7-a9c1-480a-ac86-ed9d13993d23
2026-09-07 03:15:22,166 - DEBUG - Requesting: http://10.0.0.186:8082/virtual-machine-interface/8a6057c3-7379-4724-a388-acb554acc9f1
2026-09-07 03:15:23,345 - 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=5.90 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=0.990 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 = 0.990/3.444/5.899/2.454 ms')
2026-09-07 03:15:23,345 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-61375844-27031052 passed
2026-09-07 03:15:23,466 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-09-07 03:15:23,466 - DEBUG - Waiting to SSH to VM ctest-TestQos-61375844-27031052, IP 23.150.121.196, Port 22
2026-09-07 03:15:23,544 - DEBUG - Error on ssh to ubuntu@169.254.0.3:22, result: /bin/bash: connect: Connection refused
/bin/bash: line 1: /dev/tcp/169.254.0.3/22: Connection refused {'failed': True, 'command': '(echo > /dev/tcp/169.254.0.3/22)', 'real_command': '/bin/bash -l -c "(echo > /dev/tcp/169.254.0.3/22)"', 'return_code': 1, 'succeeded': False, 'stderr': ''}
2026-09-07 03:15:23,636 - DEBUG - VM ctest-TestQos-61375844-27031052 is NOT ready for SSH connections, VM status: ACTIVE
2026-09-07 03:15:28,637 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-09-07 03:15:28,637 - DEBUG - Waiting to SSH to VM ctest-TestQos-61375844-27031052, IP 23.150.121.196, Port 22
2026-09-07 03:15:28,705 - DEBUG - Error on ssh to ubuntu@169.254.0.3:22, result: /bin/bash: connect: Connection refused
/bin/bash: line 1: /dev/tcp/169.254.0.3/22: Connection refused {'failed': True, 'command': '(echo > /dev/tcp/169.254.0.3/22)', 'real_command': '/bin/bash -l -c "(echo > /dev/tcp/169.254.0.3/22)"', 'return_code': 1, 'succeeded': False, 'stderr': ''}
2026-09-07 03:15:28,805 - DEBUG - VM ctest-TestQos-61375844-27031052 is NOT ready for SSH connections, VM status: ACTIVE
2026-09-07 03:15:33,806 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-09-07 03:15:33,807 - DEBUG - Waiting to SSH to VM ctest-TestQos-61375844-27031052, IP 23.150.121.196, Port 22
2026-09-07 03:15:33,982 - DEBUG - VM ctest-TestQos-61375844-27031052 is ready for SSH connections
2026-09-07 03:15:33,982 - INFO - Waiting for VM ctest-TestQos-61375844-73243770 to be up..
2026-09-07 03:15:34,080 - DEBUG - VM is in ACTIVE state now
2026-09-07 03:15:34,080 - INFO - VM name : ctest-TestQos-61375844-73243770
2026-09-07 03:15:34,171 - DEBUG - VM ctest-TestQos-61375844-73243770 ID is ad7a78dc-0577-4465-aafe-49d8427963e5
2026-09-07 03:15:34,171 - DEBUG - VM ctest-TestQos-61375844-73243770 launched on Node an-jenkins-deploy-platform-ansible-os-6258-2
2026-09-07 03:15:34,274 - DEBUG - Requesting: http://10.0.0.186:8082/virtual-machine/ad7a78dc-0577-4465-aafe-49d8427963e5
2026-09-07 03:15:34,291 - DEBUG - Requesting: http://10.0.0.186:8082/virtual-machine-interface/a50b8b55-6fad-4e99-a774-f6a134ae8ee6
2026-09-07 03:15:35,471 - 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=10.2 ms\r\n64 bytes from 169.254.0.4: icmp_seq=2 ttl=63 time=0.628 ms\r\n\r\n--- 169.254.0.4 ping statistics ---\r\n2 packets transmitted, 2 received, 0% packet loss, time 1001ms\r\nrtt min/avg/max/mdev = 0.628/5.390/10.152/4.762 ms')
2026-09-07 03:15:35,471 - INFO - Ping to Metadata IP 169.254.0.4 of VM ctest-TestQos-61375844-73243770 passed
2026-09-07 03:15:35,542 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-09-07 03:15:35,543 - DEBUG - Waiting to SSH to VM ctest-TestQos-61375844-73243770, IP 34.154.149.3, Port 22
2026-09-07 03:15:35,610 - 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': ''}
2026-09-07 03:15:35,704 - DEBUG - VM ctest-TestQos-61375844-73243770 is NOT ready for SSH connections, VM status: ACTIVE
2026-09-07 03:15:40,705 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-09-07 03:15:40,705 - DEBUG - Waiting to SSH to VM ctest-TestQos-61375844-73243770, IP 34.154.149.3, Port 22
2026-09-07 03:15:40,881 - DEBUG - VM ctest-TestQos-61375844-73243770 is ready for SSH connections
2026-09-07 03:15:40,884 - INFO - ================================================================================
2026-09-07 03:15:40,884 - INFO - STARTING TEST : test_qos_remark_dscp_on_vmi
2026-09-07 03:15:40,884 - INFO - TEST DESCRIPTION : Create a qos config for remarking DSCP 1 to 10
Have VMs A, B
Apply the qos config to VM A
Validate that packets from A to B have DSCP marked correctly
2026-09-07 03:15:42,200 - DEBUG - Nothing to compare xmpp stats {'10.0.0.189': {'10.20.0.25': '0', '10.20.0.29': '0'}, '10.0.0.190': {'10.20.0.254': '0', '10.20.0.25': '0'}} with
2026-09-07 03:15:42,200 - INFO - Initial checks done. Running the testcase now
2026-09-07 03:15:42,201 - INFO -
2026-09-07 03:15:42,208 - DEBUG - FC Dict is {'fc_id': 0, 'dscp': 10, 'dot1p': 1, 'exp': 1, 'connections': }
2026-09-07 03:15:42,476 - INFO - Created FC ['default-global-system-config', 'default-global-qos-config', 'ctest-fc-58370532'], UUID 4a541d12-aa68-4b27-aab8-997847b19334
2026-09-07 03:15:42,848 - INFO - Created QosConfig ['default-domain', 'ctest-TestQos-61375844', 'ctest-qos_config-08630943'], UUID: d336158c-db2a-4028-ac61-b25e76c4c99d
2026-09-07 03:15:42,897 - INFO - Applying qos-config on VM 21a98b9c-bce5-4f23-8d8f-b5307ebeb69c
2026-09-07 03:15:43,159 - DEBUG - VM is in ACTIVE state now
2026-09-07 03:15:43,408 - DEBUG - Requesting: http://10.0.0.186:8082/virtual-machine/b46eae48-e65f-42da-9d00-54d67b7334d2
2026-09-07 03:15:43,417 - DEBUG - Requesting: http://10.0.0.186:8082/virtual-machine-interface/21a98b9c-bce5-4f23-8d8f-b5307ebeb69c
2026-09-07 03:15:43,427 - DEBUG - Requesting: http://10.0.0.186:8082/instance-ip/15f7851c-cd50-428d-8e96-84e98ec9d5b0
2026-09-07 03:15:43,438 - DEBUG - Requesting: http://10.0.0.186:8082/instance-ip/cf30f00e-3c65-41b2-8572-d882e984d4a6
2026-09-07 03:15:43,670 - DEBUG - VM is in ACTIVE state now
2026-09-07 03:15:43,912 - DEBUG - Requesting: http://10.0.0.186:8082/virtual-machine/2f7e3aa7-a9c1-480a-ac86-ed9d13993d23
2026-09-07 03:15:43,924 - DEBUG - Requesting: http://10.0.0.186:8082/virtual-machine-interface/8a6057c3-7379-4724-a388-acb554acc9f1
2026-09-07 03:15:43,935 - DEBUG - Requesting: http://10.0.0.186:8082/instance-ip/0ca989b5-04c6-4d2b-92ad-022a31328901
2026-09-07 03:15:43,947 - DEBUG - Requesting: http://10.0.0.186:8082/instance-ip/5b2890c4-a341-4f55-afc2-523c16701c77
2026-09-07 03:15:43,994 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-09-07 03:15:43,995 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-09-07 03:15:43,995 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-09-07 03:15:43,995 - INFO - Starting hping3 on ctest-TestQos-61375844-42042589, args: --destport 20000 --baseport 10000 --count 20000 --interval 1 --udp --tos 4 --keep --numeric
2026-09-07 03:15:43,995 - DEBUG - Hping3 cmd : hping3 --destport 20000 --baseport 10000 --count 20000 --interval 1 --udp --tos 4 --keep --numeric 23.150.121.196 1>/tmp/hping_ctest-random-33956865.log 2>/tmp/hping_ctest-random-33956865.result
2026-09-07 03:15:43,995 - DEBUG - Running remote_cmd, Cmd : hping3 --destport 20000 --baseport 10000 --count 20000 --interval 1 --udp --tos 4 --keep --numeric 23.150.121.196 1>/tmp/hping_ctest-random-33956865.log 2>/tmp/hping_ctest-random-33956865.result, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.189, gateway password: c0ntrail123
2026-09-07 03:15:43,995 - DEBUG - nohup hping3 --destport 20000 --baseport 10000 --count 20000 --interval 1 --udp --tos 4 --keep --numeric 23.150.121.196 1>/tmp/hping_ctest-random-33956865.log 2>/tmp/hping_ctest-random-33956865.result & echo $! > /tmp/hping_ctest-random-33956865.pid
2026-09-07 03:16:29,403 - DEBUG - None
2026-09-07 03:16:34,576 - DEBUG - Forward flow: {'index': '296000', 'rflow': '308840', 'sip': '23.150.121.195', 'sport': '10000', 'dip': '23.150.121.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': '29', 'underlay_udp_sport': '59510', 'ttl': '0', 'qos_id': '0', 'gen_id': '1', 'tcp_seq': '0', 'oflow_bytes': '0', 'oflow_packets': '0', 'underlay_gw_index': '-1'}
2026-09-07 03:16:34,577 - DEBUG - Reverse flow: {'index': '308840', 'rflow': '296000', 'sip': '23.150.121.196', 'sport': '20000', 'dip': '23.150.121.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': '29', 'underlay_udp_sport': '60316', 'ttl': '0', 'qos_id': '0', 'gen_id': '1', 'tcp_seq': '0', 'oflow_bytes': '0', 'oflow_packets': '0', 'underlay_gw_index': '-1'}
2026-09-07 03:16:34,577 - DEBUG - The filter pattern is ['udp', 'and', 'src port 59510']
2026-09-07 03:16:34,577 - DEBUG - The filter string is '(udp and src port 59510)'
2026-09-07 03:16:34,653 - DEBUG - Executing command: sudo tcpdump -nni enp5s0 -U -vvxx '(udp and src port 59510)' -w /tmp/enp5s0_ctest-random-33958930.pcap
2026-09-07 03:16:39,751 - DEBUG - Executing command: sudo kill $(ps -ef|grep tcpdump | grep pcap| awk '{print $2}')
2026-09-07 03:16:41,753 - DEBUG - Ensuring hping3 instance with result file /tmp/hping_ctest-random-33956865.result on ctest-TestQos-61375844-42042589 is stopped
2026-09-07 03:16:41,754 - DEBUG - Running remote_cmd, Cmd : cat /tmp/hping_ctest-random-33956865.pid | xargs kill , host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.189, gateway password: c0ntrail123
2026-09-07 03:16:41,754 - DEBUG - cat /tmp/hping_ctest-random-33956865.pid | xargs kill
2026-09-07 03:16:42,165 - DEBUG - None
2026-09-07 03:16:42,165 - DEBUG - Running remote_cmd, Cmd : cat /tmp/hping_ctest-random-33956865.result, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.189, gateway password: c0ntrail123
2026-09-07 03:16:42,165 - DEBUG - cat /tmp/hping_ctest-random-33956865.result
2026-09-07 03:16:42,401 - DEBUG - --- 23.150.121.196 hping statistic ---
13 packets transmitted, 13 packets received, 0% packet loss
round-trip min/avg/max = 16.8/6012.3/12018.2 ms
2026-09-07 03:16:42,401 - DEBUG - Running remote_cmd, Cmd : cat /tmp/hping_ctest-random-33956865.log, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.189, gateway password: c0ntrail123
2026-09-07 03:16:42,401 - DEBUG - cat /tmp/hping_ctest-random-33956865.log
2026-09-07 03:16:42,625 - DEBUG - HPING 23.150.121.196 (eth0 23.150.121.196): udp mode set, 28 headers + 0 data bytes
ICMP Port Unreachable from ip=23.150.121.196
status=0 port=10000 seq=0
ICMP Port Unreachable from ip=23.150.121.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=23.150.121.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=23.150.121.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=23.150.121.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=23.150.121.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=23.150.121.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=23.150.121.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=23.150.121.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=23.150.121.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=23.150.121.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=23.150.121.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=23.150.121.196
status=1 port=10000 seq=0
2026-09-07 03:16:42,626 - DEBUG - Hping3 stats: {'sent': '13', 'received': '13', 'loss': '0', 'rtt_min': '16.8', 'rtt_avg': '6012.3', 'rtt_max': '12018.2'}
2026-09-07 03:16:42,626 - DEBUG - Executing command: sudo tcpdump -nnr /tmp/enp5s0_ctest-random-33958930.pcap | wc -l
2026-09-07 03:16:42,645 - DEBUG - STDOUT: 16
2026-09-07 03:16:42,645 - DEBUG - STDERR: reading from file /tmp/enp5s0_ctest-random-33958930.pcap, link-type EN10MB (Ethernet), snapshot length 262144
2026-09-07 03:16:42,646 - DEBUG - 16 packets are found in tcpdump output file /tmp/enp5s0_ctest-random-33958930.pcap but expected 1, which is fine
2026-09-07 03:16:42,646 - INFO - 16 packets are found in tcpdump output as expected
2026-09-07 03:16:42,646 - DEBUG - Executing command: sudo kill $(ps -ef|grep tcpdump | grep pcap| awk '{print $2}')
2026-09-07 03:16:44,711 - DEBUG - ['/contrail-test/enp5s0_ctest-random-33958930.pcap']
2026-09-07 03:16:44,711 - DEBUG - Verifying for packet number 0
2026-09-07 03:16:44,711 - DEBUG - Validated DSCP marking of 10
2026-09-07 03:16:44,712 - DEBUG - Verifying for packet number 1
2026-09-07 03:16:44,712 - DEBUG - Validated DSCP marking of 10
2026-09-07 03:16:44,712 - DEBUG - Verifying for packet number 2
2026-09-07 03:16:44,712 - DEBUG - Validated DSCP marking of 10
2026-09-07 03:16:44,712 - DEBUG - Verifying for packet number 3
2026-09-07 03:16:44,712 - DEBUG - Validated DSCP marking of 10
2026-09-07 03:16:44,712 - INFO - Packet QoS marking validation passed
2026-09-07 03:16:44,712 - DEBUG - Executing command: sudo tcpdump -nnr /tmp/enp5s0_ctest-random-33958930.pcap | wc -l
2026-09-07 03:16:44,730 - DEBUG - STDOUT: 16
2026-09-07 03:16:44,730 - DEBUG - STDERR: reading from file /tmp/enp5s0_ctest-random-33958930.pcap, link-type EN10MB (Ethernet), snapshot length 262144
2026-09-07 03:16:44,730 - DEBUG - 16 packets are found in tcpdump output file /tmp/enp5s0_ctest-random-33958930.pcap but expected 1, which is fine
2026-09-07 03:16:44,730 - INFO - 16 packets are found in tcpdump output as expected
2026-09-07 03:16:44,730 - DEBUG - Executing command: sudo kill $(ps -ef|grep tcpdump | grep pcap| awk '{print $2}')
2026-09-07 03:16:46,796 - DEBUG - ['/contrail-test/enp5s0_ctest-random-33958930.pcap']
2026-09-07 03:16:46,796 - DEBUG - Verifying for packet number 0
2026-09-07 03:16:46,796 - DEBUG - Interface enp5s0 does not seem to be a tagged intf. Skipping dot1p check
2026-09-07 03:16:46,796 - DEBUG - Verifying for packet number 1
2026-09-07 03:16:46,797 - DEBUG - Interface enp5s0 does not seem to be a tagged intf. Skipping dot1p check
2026-09-07 03:16:46,797 - DEBUG - Verifying for packet number 2
2026-09-07 03:16:46,797 - DEBUG - Interface enp5s0 does not seem to be a tagged intf. Skipping dot1p check
2026-09-07 03:16:46,797 - DEBUG - Verifying for packet number 3
2026-09-07 03:16:46,797 - DEBUG - Interface enp5s0 does not seem to be a tagged intf. Skipping dot1p check
2026-09-07 03:16:46,797 - INFO - Packet QoS marking validation passed
2026-09-07 03:16:46,919 - INFO - Removing qos-config on VM 21a98b9c-bce5-4f23-8d8f-b5307ebeb69c
2026-09-07 03:16:46,996 - INFO - Deleting Qos config ['default-domain', 'ctest-TestQos-61375844', 'ctest-qos_config-08630943'], UUID: d336158c-db2a-4028-ac61-b25e76c4c99d
2026-09-07 03:16:47,108 - INFO - Deleting FC ['default-global-system-config', 'default-global-qos-config', 'ctest-fc-58370532'], UUID: 4a541d12-aa68-4b27-aab8-997847b19334
2026-09-07 03:16:48,440 - DEBUG - No XMPP flaps were noticed during the test
2026-09-07 03:16:48,440 - INFO - --------------------------------------------------------------------------------
2026-09-07 03:16:48,441 - INFO - Deleting VM ctest-TestQos-61375844-73243770
2026-09-07 03:16:48,516 - INFO - Deleting VM ctest-TestQos-61375844-27031052
2026-09-07 03:16:48,589 - INFO - Deleting VM ctest-TestQos-61375844-42042589
2026-09-07 03:16:48,668 - INFO - Deleting VN ctest-vn-93631710
2026-09-07 03:16:48,716 - DEBUG - VN d6640534-2e1a-4c14-bfb9-c0115574d86e still in use: Unable to complete operation on network d6640534-2e1a-4c14-bfb9-c0115574d86e. There are one or more ports still in use on the network.
Neutron server returns request_ids: ['req-e3fdf73c-3f78-4f3e-8f28-a3b5db38963b']
2026-09-07 03:16:48,717 - WARNING - Deleting VN ctest-vn-93631710 failed..Will retry
2026-09-07 03:16:50,824 - DEBUG - VN d6640534-2e1a-4c14-bfb9-c0115574d86e still in use: Unable to complete operation on network d6640534-2e1a-4c14-bfb9-c0115574d86e. There are one or more ports still in use on the network.
Neutron server returns request_ids: ['req-62232900-6a20-4850-9b9a-464e70365328']
2026-09-07 03:16:50,825 - WARNING - Deleting VN ctest-vn-93631710 failed..Will retry
2026-09-07 03:16:53,083 - DEBUG - Response for deleting network ()
2026-09-07 03:16:53,083 - INFO - Deleting VN ctest-vn-58401712
2026-09-07 03:16:53,309 - DEBUG - Response for deleting network ()
2026-09-07 03:16:54,226 - INFO - Deleted project: ctest-TestQos-61375844, ID : 6b0df0b8-ab07-4a93-a949-f97c3e6ef45d