2025-10-30 21:57:15,435 - INFO - Domain Default found not creating
2025-10-30 21:57:15,815 - INFO - Project ctest-TestRoutersBasic-69917953 not found, creating it
2025-10-30 21:57:16,603 - INFO - Created Project:ctest-TestRoutersBasic-69917953, ID : e82e3693-af54-42bf-be6a-c579889d4e6c 
2025-10-30 21:57:19,016 - INFO - ================================================================================
2025-10-30 21:57:19,016 - INFO - STARTING TEST    : test_basic_snat_behavior_without_external_connectivity
2025-10-30 21:57:19,016 - INFO - TEST DESCRIPTION : Create an external network, a router
        set router-gateway to external network
        launch a private network and attach it to router
        validate left vm pinging right vm through Snat
       
2025-10-30 21:57:19,369 - DEBUG - Nothing to compare xmpp stats {'10.0.0.245': {'10.20.0.14': '0'}} with
2025-10-30 21:57:19,369 - INFO - Initial checks done. Running the testcase now
2025-10-30 21:57:19,369 - INFO - 
2025-10-30 21:57:20,280 - INFO - Default SG to be edited for allow all on project: ctest-TestRoutersBasic-69917953
2025-10-30 21:57:20,386 - INFO - Adding rules to the default security group in Project ctest-TestRoutersBasic-69917953
2025-10-30 21:57:20,790 - DEBUG - Reading firewall policy {'fq_name': ['default-domain', 'ctest-TestRoutersBasic-69917953', 'default']}
2025-10-30 21:57:21,271 - DEBUG - Response for create_network : {'network': {'id': '70391f25-c6d8-498b-9ceb-78a52ac84d69', 'name': 'ctest-vn-98184388', 'tenant_id': 'e82e3693af5442bfbe6ac579889d4e6c', 'project_id': 'e82e3693af5442bfbe6ac579889d4e6c', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': False, 'mtu': 0, 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestRoutersBasic-69917953', 'ctest-vn-98184388'], 'port_security_enabled': True, 'description': ''}}
2025-10-30 21:57:21,450 - DEBUG - Response for create_subnet : {'subnet': {'id': '280ee7e5-7d5a-43bf-b5e3-7bfd3d8aac83', 'name': '', 'tenant_id': 'e82e3693af5442bfbe6ac579889d4e6c', 'network_id': '70391f25-c6d8-498b-9ceb-78a52ac84d69', 'ip_version': 4, 'cidr': '195.148.45.128/26', 'allocation_pools': [{'start': '195.148.45.130', 'end': '195.148.45.190'}], 'gateway_ip': '195.148.45.129', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '195.148.45.130', 'tags': [], 'project_id': 'e82e3693af5442bfbe6ac579889d4e6c'}}
2025-10-30 21:57:21,473 - INFO - Created VN ctest-vn-98184388
2025-10-30 21:57:21,525 - DEBUG - VN ctest-vn-98184388 UUID is 70391f25-c6d8-498b-9ceb-78a52ac84d69
2025-10-30 21:57:22,069 - DEBUG - Response for create_network : {'network': {'id': 'e2b28ff9-80bf-4b43-a883-7031d1a77ead', 'name': 'ctest-ext_vn-25568605', 'tenant_id': 'e82e3693af5442bfbe6ac579889d4e6c', 'project_id': 'e82e3693af5442bfbe6ac579889d4e6c', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': True, 'mtu': 0, 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestRoutersBasic-69917953', 'ctest-ext_vn-25568605'], 'port_security_enabled': True, 'description': ''}}
2025-10-30 21:57:22,266 - DEBUG - Response for create_subnet : {'subnet': {'id': '4713858a-7399-4fe1-a022-de2ce3eda141', 'name': '', 'tenant_id': 'e82e3693af5442bfbe6ac579889d4e6c', 'network_id': 'e2b28ff9-80bf-4b43-a883-7031d1a77ead', 'ip_version': 4, 'cidr': '202.199.13.192/26', 'allocation_pools': [{'start': '202.199.13.194', 'end': '202.199.13.254'}], 'gateway_ip': '202.199.13.193', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '202.199.13.194', 'tags': [], 'project_id': 'e82e3693af5442bfbe6ac579889d4e6c'}}
2025-10-30 21:57:22,290 - INFO - Created VN ctest-ext_vn-25568605
2025-10-30 21:57:22,350 - DEBUG - VN ctest-ext_vn-25568605 UUID is e2b28ff9-80bf-4b43-a883-7031d1a77ead
2025-10-30 21:57:22,662 - DEBUG - Services list from nova: [, , ]
2025-10-30 21:57:24,397 - INFO - VM ([]) created on node: (cn-jenkins-deploy-platform-ansible-os-4555-1), Zone: (nova:cn-jenkins-deploy-platform-ansible-os-4555-1)
2025-10-30 21:57:25,918 - INFO - VM ([]) created on node: (cn-jenkins-deploy-platform-ansible-os-4555-1), Zone: (nova:cn-jenkins-deploy-platform-ansible-os-4555-1)
2025-10-30 21:57:25,994 - INFO - Setting gateway for router d152a933-d215-4f90-8bd6-8ec37a6c9080 to network e2b28ff9-80bf-4b43-a883-7031d1a77ead 
2025-10-30 21:57:26,083 - INFO - Adding interface with subnet_id 280ee7e5-7d5a-43bf-b5e3-7bfd3d8aac83, port_id None to router d152a933-d215-4f90-8bd6-8ec37a6c9080
2025-10-30 21:57:26,414 - INFO - Waiting for VM ctest-TestRoutersBasic-69917953-08446332 to be up..
2025-10-30 21:57:26,555 - DEBUG - VM  is still in BUILD state, Expected: ACTIVE
2025-10-30 21:57:31,692 - DEBUG - VM  is in ACTIVE state now
2025-10-30 21:57:31,692 - INFO - VM name : ctest-TestRoutersBasic-69917953-08446332
2025-10-30 21:57:31,803 - DEBUG - VM ctest-TestRoutersBasic-69917953-08446332 ID is 1cd31012-3138-415f-8e71-ca46184dd49f
2025-10-30 21:57:31,832 - DEBUG - VM ctest-TestRoutersBasic-69917953-08446332 launched on Node cn-jenkins-deploy-platform-ansible-os-4555-1
2025-10-30 21:57:31,931 - DEBUG - Requesting: http://10.0.0.245:8082/virtual-machine/1cd31012-3138-415f-8e71-ca46184dd49f
2025-10-30 21:57:32,236 - DEBUG - Requesting: http://10.0.0.245:8082/virtual-machine/1cd31012-3138-415f-8e71-ca46184dd49f
2025-10-30 21:57:32,274 - DEBUG - Requesting: http://10.0.0.245:8082/virtual-machine-interface/b5b42d01-a10a-4ea7-b359-2c3073083932
2025-10-30 21:57:35,533 - 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 1001ms')
2025-10-30 21:57:35,534 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestRoutersBasic-69917953-08446332 failed!
2025-10-30 21:57:35,601 - DEBUG - Gateway for vn default-domain:ctest-TestRoutersBasic-69917953:ctest-vn-98184388 is 195.148.45.129 and allocation pool is NOT set
2025-10-30 21:57:37,680 - 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=4.26 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=1.26 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.258/2.759/4.261/1.501 ms')
2025-10-30 21:57:37,680 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-TestRoutersBasic-69917953-08446332 passed
2025-10-30 21:57:37,862 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-30 21:57:37,862 - DEBUG - Waiting to SSH to VM ctest-TestRoutersBasic-69917953-08446332, IP 195.148.45.131, Port 22
2025-10-30 21:57:37,954 - 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-30 21:57:38,142 - DEBUG - VM ctest-TestRoutersBasic-69917953-08446332 is NOT ready for SSH connections, VM status: ACTIVE
2025-10-30 21:57:43,143 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-30 21:57:43,143 - DEBUG - Waiting to SSH to VM ctest-TestRoutersBasic-69917953-08446332, IP 195.148.45.131, Port 22
2025-10-30 21:57:43,342 - DEBUG - VM ctest-TestRoutersBasic-69917953-08446332 is ready for SSH connections
2025-10-30 21:57:43,342 - INFO - Waiting for VM ctest-TestRoutersBasic-69917953-59724017 to be up..
2025-10-30 21:57:43,481 - DEBUG - VM  is in ACTIVE state now
2025-10-30 21:57:43,482 - INFO - VM name : ctest-TestRoutersBasic-69917953-59724017
2025-10-30 21:57:43,674 - DEBUG - VM ctest-TestRoutersBasic-69917953-59724017 ID is 35f0f258-c36f-456f-b436-52cc3b1b4816
2025-10-30 21:57:43,675 - DEBUG - VM ctest-TestRoutersBasic-69917953-59724017 launched on Node cn-jenkins-deploy-platform-ansible-os-4555-1
2025-10-30 21:57:43,874 - DEBUG - Requesting: http://10.0.0.245:8082/virtual-machine/35f0f258-c36f-456f-b436-52cc3b1b4816
2025-10-30 21:57:43,895 - DEBUG - Requesting: http://10.0.0.245:8082/virtual-machine-interface/dab7b94a-3c8b-4bfd-a0b0-e2a7a5f2eb39
2025-10-30 21:57:45,233 - 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.81 ms\r\n64 bytes from 169.254.0.4: icmp_seq=2 ttl=63 time=0.803 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.803/2.308/3.814/1.505 ms')
2025-10-30 21:57:45,233 - INFO - Ping to Metadata IP 169.254.0.4 of VM ctest-TestRoutersBasic-69917953-59724017 passed
2025-10-30 21:57:45,413 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-30 21:57:45,414 - DEBUG - Waiting to SSH to VM ctest-TestRoutersBasic-69917953-59724017, IP 202.199.13.195, Port 22
2025-10-30 21:57:45,607 - DEBUG - VM ctest-TestRoutersBasic-69917953-59724017 is ready for SSH connections
2025-10-30 21:57:45,608 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-30 21:57:45,608 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 3 -W 1  202.199.13.195, host_string: cirros@169.254.0.3, password: cubswin:)gateway: ubuntu@10.0.0.245, gateway password: c0ntrail123
2025-10-30 21:57:45,608 - DEBUG - ping -s 56 -c 3 -W 1  202.199.13.195
2025-10-30 21:57:49,722 - DEBUG - PING 202.199.13.195 (202.199.13.195): 56 data bytes
64 bytes from 202.199.13.195: seq=0 ttl=62 time=9.100 ms
64 bytes from 202.199.13.195: seq=1 ttl=62 time=2.260 ms
64 bytes from 202.199.13.195: seq=2 ttl=62 time=1.983 ms
--- 202.199.13.195 ping statistics ---
3 packets transmitted, 3 packets received, 0% packet loss
round-trip min/avg/max = 1.983/4.447/9.100 ms
2025-10-30 21:57:49,722 - INFO - Ping to IP 202.199.13.195 from VM ctest-TestRoutersBasic-69917953-08446332 passed
2025-10-30 21:57:49,722 - INFO - Deleting interface with subnet_id 280ee7e5-7d5a-43bf-b5e3-7bfd3d8aac83, port_id None from router d152a933-d215-4f90-8bd6-8ec37a6c9080
2025-10-30 21:57:50,053 - INFO - Deleting VM ctest-TestRoutersBasic-69917953-59724017
2025-10-30 21:57:50,122 - INFO - Deleting VM ctest-TestRoutersBasic-69917953-08446332
2025-10-30 21:57:50,218 - INFO - Deleting VN ctest-ext_vn-25568605 
2025-10-30 21:57:50,288 - DEBUG - VN e2b28ff9-80bf-4b43-a883-7031d1a77ead still in use: Unable to complete operation on network e2b28ff9-80bf-4b43-a883-7031d1a77ead. There are one or more ports still in use on the network.
Neutron server returns request_ids: ['req-8ac53855-3c1e-4d2d-a2c4-fe63e48c2a39']
2025-10-30 21:57:50,288 - WARNING - Deleting VN ctest-ext_vn-25568605 failed..Will retry
2025-10-30 21:57:52,546 - DEBUG - Response for deleting network ()
2025-10-30 21:57:52,547 - INFO - Deleting VN ctest-vn-98184388 
2025-10-30 21:57:52,685 - DEBUG - Response for deleting network ()
2025-10-30 21:57:53,009 - DEBUG - No XMPP flaps were noticed during the test
2025-10-30 21:57:53,009 - INFO - END TEST : test_basic_snat_behavior_without_external_connectivity : PASSED[0:00:34]
2025-10-30 21:57:53,009 - INFO - --------------------------------------------------------------------------------
2025-10-30 21:57:53,910 - INFO - Deleted project: ctest-TestRoutersBasic-69917953, ID : e82e3693-af54-42bf-be6a-c579889d4e6c