2025-10-17 17:42:32,169 - INFO - Domain Default found not creating
2025-10-17 17:42:32,408 - INFO - Project ctest-TestRouters-60746235 not found, creating it
2025-10-17 17:42:32,923 - INFO - Created Project:ctest-TestRouters-60746235, ID : ec7534a4-fb73-43c4-8639-d724a40ab84a 
2025-10-17 17:42:35,303 - INFO - ================================================================================
2025-10-17 17:42:35,303 - INFO - STARTING TEST    : test_basic_router_behavior
2025-10-17 17:42:35,304 - INFO - TEST DESCRIPTION : Validate a router is able to route packets between two VNs
        Create a router
        Create 2 VNs, and a VM in each
        Add router port from each VN
        Ping between VMs
        
2025-10-17 17:42:35,607 - DEBUG - Nothing to compare xmpp stats {'10.0.0.33': {'10.20.0.17': '0'}} with
2025-10-17 17:42:35,607 - INFO - Initial checks done. Running the testcase now
2025-10-17 17:42:35,607 - INFO - 
2025-10-17 17:42:36,285 - DEBUG - Response for create_network : {'network': {'id': '79858f43-c2dd-472f-8fed-f06297c8c979', 'name': 'ctest-vn1-73032381', 'tenant_id': 'ec7534a4fb7343c48639d724a40ab84a', 'project_id': 'ec7534a4fb7343c48639d724a40ab84a', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': False, 'mtu': 0, 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestRouters-60746235', 'ctest-vn1-73032381'], 'port_security_enabled': True, 'description': ''}}
2025-10-17 17:42:36,446 - DEBUG - Response for create_subnet : {'subnet': {'id': 'a91def34-ce99-40be-8c3a-e01bc5be6310', 'name': '', 'tenant_id': 'ec7534a4fb7343c48639d724a40ab84a', 'network_id': '79858f43-c2dd-472f-8fed-f06297c8c979', 'ip_version': 4, 'cidr': '117.184.251.0/26', 'allocation_pools': [{'start': '117.184.251.2', 'end': '117.184.251.62'}], 'gateway_ip': '117.184.251.1', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '117.184.251.2', 'tags': [], 'project_id': 'ec7534a4fb7343c48639d724a40ab84a'}}
2025-10-17 17:42:36,464 - INFO - Created VN ctest-vn1-73032381
2025-10-17 17:42:36,517 - DEBUG - VN ctest-vn1-73032381 UUID is 79858f43-c2dd-472f-8fed-f06297c8c979
2025-10-17 17:42:36,991 - DEBUG - Response for create_network : {'network': {'id': 'a60da9fd-1334-4bb0-9a69-ceaa70f5e51c', 'name': 'ctest-vn2-67759257', 'tenant_id': 'ec7534a4fb7343c48639d724a40ab84a', 'project_id': 'ec7534a4fb7343c48639d724a40ab84a', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': False, 'mtu': 0, 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestRouters-60746235', 'ctest-vn2-67759257'], 'port_security_enabled': True, 'description': ''}}
2025-10-17 17:42:37,181 - DEBUG - Response for create_subnet : {'subnet': {'id': '7e50cd4d-5cf2-426c-bb23-310f8a811a0c', 'name': '', 'tenant_id': 'ec7534a4fb7343c48639d724a40ab84a', 'network_id': 'a60da9fd-1334-4bb0-9a69-ceaa70f5e51c', 'ip_version': 4, 'cidr': '118.38.214.0/26', 'allocation_pools': [{'start': '118.38.214.2', 'end': '118.38.214.62'}], 'gateway_ip': '118.38.214.1', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '118.38.214.2', 'tags': [], 'project_id': 'ec7534a4fb7343c48639d724a40ab84a'}}
2025-10-17 17:42:37,202 - INFO - Created VN ctest-vn2-67759257
2025-10-17 17:42:37,256 - DEBUG - VN ctest-vn2-67759257 UUID is a60da9fd-1334-4bb0-9a69-ceaa70f5e51c
2025-10-17 17:42:37,449 - DEBUG - Services list from nova: [, , ]
2025-10-17 17:42:38,928 - INFO - VM ([]) created on node: (cn-jenkins-deploy-platform-ansible-os-4356-1), Zone: (nova:cn-jenkins-deploy-platform-ansible-os-4356-1)
2025-10-17 17:42:40,380 - INFO - VM ([]) created on node: (cn-jenkins-deploy-platform-ansible-os-4356-1), Zone: (nova:cn-jenkins-deploy-platform-ansible-os-4356-1)
2025-10-17 17:42:40,447 - INFO - Adding interface with subnet_id a91def34-ce99-40be-8c3a-e01bc5be6310, port_id None to router 7a11f2a8-7a38-44b5-b6fa-77bcc4d92d61
2025-10-17 17:42:40,719 - INFO - Waiting for VM ctest-vn1-vm1-10232956 to be up..
2025-10-17 17:42:40,817 - DEBUG - VM  is still in BUILD state, Expected: ACTIVE
2025-10-17 17:42:45,938 - DEBUG - VM  is in ACTIVE state now
2025-10-17 17:42:45,938 - INFO - VM name : ctest-vn1-vm1-10232956
2025-10-17 17:42:46,070 - DEBUG - VM ctest-vn1-vm1-10232956 ID is 81771320-ca54-4852-9515-b2a7135e3ba0
2025-10-17 17:42:46,099 - DEBUG - VM ctest-vn1-vm1-10232956 launched on Node cn-jenkins-deploy-platform-ansible-os-4356-1
2025-10-17 17:42:46,188 - DEBUG - Requesting: http://10.0.0.33:8082/virtual-machine/81771320-ca54-4852-9515-b2a7135e3ba0
2025-10-17 17:42:46,499 - DEBUG - Requesting: http://10.0.0.33:8082/virtual-machine/81771320-ca54-4852-9515-b2a7135e3ba0
2025-10-17 17:42:46,544 - DEBUG - Requesting: http://10.0.0.33:8082/virtual-machine-interface/855fae8c-bb91-43c6-b55d-834dace238ff
2025-10-17 17:42:49,861 - 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 1024ms')
2025-10-17 17:42:49,861 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-vn1-vm1-10232956 failed!
2025-10-17 17:42:49,961 - DEBUG - Gateway for vn default-domain:ctest-TestRouters-60746235:ctest-vn1-73032381 is 117.184.251.1 and allocation pool is NOT set
2025-10-17 17:42:52,026 - 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=14.8 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=2.39 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 = 2.392/8.594/14.797/6.202 ms')
2025-10-17 17:42:52,026 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-vn1-vm1-10232956 passed
2025-10-17 17:42:52,180 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-17 17:42:52,181 - DEBUG - Waiting to SSH to VM ctest-vn1-vm1-10232956, IP 117.184.251.3, Port 22
2025-10-17 17:42:52,246 - DEBUG - Error on ssh to cirros@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-17 17:42:52,330 - DEBUG - VM ctest-vn1-vm1-10232956 is NOT ready for SSH connections, VM status: ACTIVE
2025-10-17 17:42:57,331 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-17 17:42:57,331 - DEBUG - Waiting to SSH to VM ctest-vn1-vm1-10232956, IP 117.184.251.3, Port 22
2025-10-17 17:42:57,524 - DEBUG - VM ctest-vn1-vm1-10232956 is ready for SSH connections
2025-10-17 17:42:57,524 - INFO - Waiting for VM ctest-vn2-vm1-82663460 to be up..
2025-10-17 17:42:57,677 - DEBUG - VM  is in ACTIVE state now
2025-10-17 17:42:57,677 - INFO - VM name : ctest-vn2-vm1-82663460
2025-10-17 17:42:57,826 - DEBUG - VM ctest-vn2-vm1-82663460 ID is a19edc2f-f212-41a3-ae7e-179379127b1e
2025-10-17 17:42:57,826 - DEBUG - VM ctest-vn2-vm1-82663460 launched on Node cn-jenkins-deploy-platform-ansible-os-4356-1
2025-10-17 17:42:57,980 - DEBUG - Requesting: http://10.0.0.33:8082/virtual-machine/a19edc2f-f212-41a3-ae7e-179379127b1e
2025-10-17 17:42:57,999 - DEBUG - Requesting: http://10.0.0.33:8082/virtual-machine-interface/e431f9a5-52b9-4c69-b254-2733d38f29b9
2025-10-17 17:42:59,304 - 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=5.15 ms\r\n64 bytes from 169.254.0.4: icmp_seq=2 ttl=63 time=0.789 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.789/2.971/5.154/2.182 ms')
2025-10-17 17:42:59,304 - INFO - Ping to Metadata IP 169.254.0.4 of VM ctest-vn2-vm1-82663460 passed
2025-10-17 17:42:59,477 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-17 17:42:59,478 - DEBUG - Waiting to SSH to VM ctest-vn2-vm1-82663460, IP 118.38.214.3, Port 22
2025-10-17 17:42:59,681 - DEBUG - VM ctest-vn2-vm1-82663460 is ready for SSH connections
2025-10-17 17:42:59,681 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-17 17:42:59,682 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 3 -W 1  118.38.214.3, host_string: cirros@169.254.0.3, password: cubswin:)gateway: ubuntu@10.0.0.33, gateway password: c0ntrail123
2025-10-17 17:42:59,682 - DEBUG - ping -s 56 -c 3 -W 1  118.38.214.3
2025-10-17 17:43:05,184 - DEBUG - PING 118.38.214.3 (118.38.214.3): 56 data bytes
--- 118.38.214.3 ping statistics ---
3 packets transmitted, 0 packets received, 100% packet loss
2025-10-17 17:43:05,185 - WARNING - Ping to IP 118.38.214.3 from VM ctest-vn1-vm1-10232956 failed
2025-10-17 17:43:05,185 - INFO - Adding interface with subnet_id 7e50cd4d-5cf2-426c-bb23-310f8a811a0c, port_id None to router 7a11f2a8-7a38-44b5-b6fa-77bcc4d92d61
2025-10-17 17:43:05,476 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-17 17:43:05,476 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 3 -W 1  118.38.214.3, host_string: cirros@169.254.0.3, password: cubswin:)gateway: ubuntu@10.0.0.33, gateway password: c0ntrail123
2025-10-17 17:43:05,476 - DEBUG - ping -s 56 -c 3 -W 1  118.38.214.3
2025-10-17 17:43:07,732 - DEBUG - PING 118.38.214.3 (118.38.214.3): 56 data bytes
64 bytes from 118.38.214.3: seq=0 ttl=63 time=3.858 ms
64 bytes from 118.38.214.3: seq=1 ttl=63 time=1.836 ms
64 bytes from 118.38.214.3: seq=2 ttl=63 time=2.122 ms
--- 118.38.214.3 ping statistics ---
3 packets transmitted, 3 packets received, 0% packet loss
round-trip min/avg/max = 1.836/2.605/3.858 ms
2025-10-17 17:43:07,733 - INFO - Ping to IP 118.38.214.3 from VM ctest-vn1-vm1-10232956 passed
2025-10-17 17:43:07,733 - INFO - Deleting interface with subnet_id a91def34-ce99-40be-8c3a-e01bc5be6310, port_id None from router 7a11f2a8-7a38-44b5-b6fa-77bcc4d92d61
2025-10-17 17:43:07,963 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-17 17:43:07,963 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 3 -W 1  118.38.214.3, host_string: cirros@169.254.0.3, password: cubswin:)gateway: ubuntu@10.0.0.33, gateway password: c0ntrail123
2025-10-17 17:43:07,964 - DEBUG - ping -s 56 -c 3 -W 1  118.38.214.3
2025-10-17 17:43:11,293 - DEBUG - PING 118.38.214.3 (118.38.214.3): 56 data bytes
--- 118.38.214.3 ping statistics ---
3 packets transmitted, 0 packets received, 100% packet loss
2025-10-17 17:43:11,294 - WARNING - Ping to IP 118.38.214.3 from VM ctest-vn1-vm1-10232956 failed
2025-10-17 17:43:11,294 - INFO - Adding interface with subnet_id a91def34-ce99-40be-8c3a-e01bc5be6310, port_id None to router 7a11f2a8-7a38-44b5-b6fa-77bcc4d92d61
2025-10-17 17:43:11,611 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-17 17:43:11,611 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 3 -W 1  118.38.214.3, host_string: cirros@169.254.0.3, password: cubswin:)gateway: ubuntu@10.0.0.33, gateway password: c0ntrail123
2025-10-17 17:43:11,611 - DEBUG - ping -s 56 -c 3 -W 1  118.38.214.3
2025-10-17 17:43:13,846 - DEBUG - PING 118.38.214.3 (118.38.214.3): 56 data bytes
64 bytes from 118.38.214.3: seq=0 ttl=63 time=1.563 ms
64 bytes from 118.38.214.3: seq=1 ttl=63 time=1.643 ms
64 bytes from 118.38.214.3: seq=2 ttl=63 time=1.295 ms
--- 118.38.214.3 ping statistics ---
3 packets transmitted, 3 packets received, 0% packet loss
round-trip min/avg/max = 1.295/1.500/1.643 ms
2025-10-17 17:43:13,846 - INFO - Ping to IP 118.38.214.3 from VM ctest-vn1-vm1-10232956 passed
2025-10-17 17:43:13,846 - INFO - Deleting interface with subnet_id 7e50cd4d-5cf2-426c-bb23-310f8a811a0c, port_id None from router 7a11f2a8-7a38-44b5-b6fa-77bcc4d92d61
2025-10-17 17:43:14,022 - INFO - Deleting interface with subnet_id a91def34-ce99-40be-8c3a-e01bc5be6310, port_id None from router 7a11f2a8-7a38-44b5-b6fa-77bcc4d92d61
2025-10-17 17:43:14,290 - INFO - Deleting VM ctest-vn2-vm1-82663460
2025-10-17 17:43:14,387 - INFO - Deleting VM ctest-vn1-vm1-10232956
2025-10-17 17:43:14,482 - INFO - Deleting VN ctest-vn2-67759257 
2025-10-17 17:43:14,553 - DEBUG - VN a60da9fd-1334-4bb0-9a69-ceaa70f5e51c still in use: Unable to complete operation on network a60da9fd-1334-4bb0-9a69-ceaa70f5e51c. There are one or more ports still in use on the network.
Neutron server returns request_ids: ['req-d2a57b2e-3718-404c-943e-a5405849942e']
2025-10-17 17:43:14,553 - WARNING - Deleting VN ctest-vn2-67759257 failed..Will retry
2025-10-17 17:43:16,749 - DEBUG - Response for deleting network ()
2025-10-17 17:43:16,749 - INFO - Deleting VN ctest-vn1-73032381 
2025-10-17 17:43:16,875 - DEBUG - Response for deleting network ()
2025-10-17 17:43:17,149 - DEBUG - No XMPP flaps were noticed during the test
2025-10-17 17:43:17,149 - INFO - END TEST : test_basic_router_behavior : PASSED[0:00:42]
2025-10-17 17:43:17,149 - INFO - --------------------------------------------------------------------------------
2025-10-17 17:43:17,910 - INFO - Deleted project: ctest-TestRouters-60746235, ID : ec7534a4-fb73-43c4-8639-d724a40ab84a