2025-10-23 23:38:03,489 - INFO - Domain Default found not creating
2025-10-23 23:38:03,645 - INFO - Project ctest-TestRoutersBasic-05291428 not found, creating it
2025-10-23 23:38:04,133 - INFO - Created Project:ctest-TestRoutersBasic-05291428, ID : 75d226e2-cf1b-4328-9cb9-ef6c87a2f152 
2025-10-23 23:38:05,727 - INFO - ================================================================================
2025-10-23 23:38:05,727 - INFO - STARTING TEST    : test_basic_snat_behavior_without_external_connectivity
2025-10-23 23:38:05,727 - 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-23 23:38:05,989 - DEBUG - Nothing to compare xmpp stats {'10.0.0.242': {'10.20.0.17': '0'}} with
2025-10-23 23:38:05,989 - INFO - Initial checks done. Running the testcase now
2025-10-23 23:38:05,989 - INFO - 
2025-10-23 23:38:06,777 - INFO - Default SG to be edited for allow all on project: ctest-TestRoutersBasic-05291428
2025-10-23 23:38:06,872 - INFO - Adding rules to the default security group in Project ctest-TestRoutersBasic-05291428
2025-10-23 23:38:07,191 - DEBUG - Reading firewall policy {'fq_name': ['default-domain', 'ctest-TestRoutersBasic-05291428', 'default']}
2025-10-23 23:38:07,486 - DEBUG - Response for create_network : {'network': {'id': '993451d5-087f-48aa-9de1-3d4d6f86b987', 'name': 'ctest-vn-70373199', 'tenant_id': '75d226e2cf1b43289cb9ef6c87a2f152', 'project_id': '75d226e2cf1b43289cb9ef6c87a2f152', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': False, 'mtu': 0, 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestRoutersBasic-05291428', 'ctest-vn-70373199'], 'port_security_enabled': True, 'description': ''}}
2025-10-23 23:38:07,719 - DEBUG - Response for create_subnet : {'subnet': {'id': '582235b5-7669-409a-a1c1-e35974d3bc06', 'name': '', 'tenant_id': '75d226e2cf1b43289cb9ef6c87a2f152', 'network_id': '993451d5-087f-48aa-9de1-3d4d6f86b987', 'ip_version': 4, 'cidr': '76.159.210.192/26', 'allocation_pools': [{'start': '76.159.210.194', 'end': '76.159.210.254'}], 'gateway_ip': '76.159.210.193', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '76.159.210.194', 'tags': [], 'project_id': '75d226e2cf1b43289cb9ef6c87a2f152'}}
2025-10-23 23:38:07,740 - INFO - Created VN ctest-vn-70373199
2025-10-23 23:38:07,795 - DEBUG - VN ctest-vn-70373199 UUID is 993451d5-087f-48aa-9de1-3d4d6f86b987
2025-10-23 23:38:08,117 - DEBUG - Response for create_network : {'network': {'id': 'f4b4f0f5-e953-404f-a7f5-fa65f7184206', 'name': 'ctest-ext_vn-29314612', 'tenant_id': '75d226e2cf1b43289cb9ef6c87a2f152', 'project_id': '75d226e2cf1b43289cb9ef6c87a2f152', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': True, 'mtu': 0, 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestRoutersBasic-05291428', 'ctest-ext_vn-29314612'], 'port_security_enabled': True, 'description': ''}}
2025-10-23 23:38:08,277 - DEBUG - Response for create_subnet : {'subnet': {'id': 'eab42468-e857-44a9-97c2-fe9ad581b3ae', 'name': '', 'tenant_id': '75d226e2cf1b43289cb9ef6c87a2f152', 'network_id': 'f4b4f0f5-e953-404f-a7f5-fa65f7184206', 'ip_version': 4, 'cidr': '47.45.131.64/26', 'allocation_pools': [{'start': '47.45.131.66', 'end': '47.45.131.126'}], 'gateway_ip': '47.45.131.65', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '47.45.131.66', 'tags': [], 'project_id': '75d226e2cf1b43289cb9ef6c87a2f152'}}
2025-10-23 23:38:08,298 - INFO - Created VN ctest-ext_vn-29314612
2025-10-23 23:38:08,351 - DEBUG - VN ctest-ext_vn-29314612 UUID is f4b4f0f5-e953-404f-a7f5-fa65f7184206
2025-10-23 23:38:08,561 - DEBUG - Services list from nova: [, , ]
2025-10-23 23:38:09,675 - INFO - VM ([]) created on node: (cn-jenkins-deploy-platform-ansible-os-4471-1), Zone: (nova:cn-jenkins-deploy-platform-ansible-os-4471-1)
2025-10-23 23:38:11,038 - INFO - VM ([]) created on node: (cn-jenkins-deploy-platform-ansible-os-4471-1), Zone: (nova:cn-jenkins-deploy-platform-ansible-os-4471-1)
2025-10-23 23:38:11,130 - INFO - Setting gateway for router 30e86fc6-3f29-4adc-bd79-955da88dab26 to network f4b4f0f5-e953-404f-a7f5-fa65f7184206 
2025-10-23 23:38:11,190 - INFO - Adding interface with subnet_id 582235b5-7669-409a-a1c1-e35974d3bc06, port_id None to router 30e86fc6-3f29-4adc-bd79-955da88dab26
2025-10-23 23:38:11,592 - INFO - Waiting for VM ctest-TestRoutersBasic-05291428-71542713 to be up..
2025-10-23 23:38:11,850 - DEBUG - VM  is still in BUILD state, Expected: ACTIVE
2025-10-23 23:38:16,952 - DEBUG - VM  is in ACTIVE state now
2025-10-23 23:38:16,952 - INFO - VM name : ctest-TestRoutersBasic-05291428-71542713
2025-10-23 23:38:17,057 - DEBUG - VM ctest-TestRoutersBasic-05291428-71542713 ID is 3be80efa-708d-4bea-abd2-96eb671bc04b
2025-10-23 23:38:17,083 - DEBUG - VM ctest-TestRoutersBasic-05291428-71542713 launched on Node cn-jenkins-deploy-platform-ansible-os-4471-1
2025-10-23 23:38:17,172 - DEBUG - Requesting: http://10.0.0.242:8082/virtual-machine/3be80efa-708d-4bea-abd2-96eb671bc04b
2025-10-23 23:38:17,512 - DEBUG - Requesting: http://10.0.0.242:8082/virtual-machine/3be80efa-708d-4bea-abd2-96eb671bc04b
2025-10-23 23:38:17,550 - DEBUG - Requesting: http://10.0.0.242:8082/virtual-machine-interface/f8a3d8a8-2cef-4cd9-9ab9-87545af96c9c
2025-10-23 23:38:20,833 - 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-23 23:38:20,833 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestRoutersBasic-05291428-71542713 failed!
2025-10-23 23:38:20,888 - DEBUG - Gateway for vn default-domain:ctest-TestRoutersBasic-05291428:ctest-vn-70373199 is 76.159.210.193 and allocation pool is NOT set
2025-10-23 23:38:22,958 - 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.72 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=5.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 = 4.724/5.048/5.373/0.324 ms')
2025-10-23 23:38:22,959 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-TestRoutersBasic-05291428-71542713 passed
2025-10-23 23:38:23,124 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-23 23:38:23,124 - DEBUG - Waiting to SSH to VM ctest-TestRoutersBasic-05291428-71542713, IP 76.159.210.195, Port 22
2025-10-23 23:38:23,280 - DEBUG - VM ctest-TestRoutersBasic-05291428-71542713 is ready for SSH connections
2025-10-23 23:38:23,280 - INFO - Waiting for VM ctest-TestRoutersBasic-05291428-95563729 to be up..
2025-10-23 23:38:23,366 - DEBUG - VM  is in ACTIVE state now
2025-10-23 23:38:23,366 - INFO - VM name : ctest-TestRoutersBasic-05291428-95563729
2025-10-23 23:38:23,444 - DEBUG - VM ctest-TestRoutersBasic-05291428-95563729 ID is 103cd27a-d064-45fd-8986-98af87a8c50f
2025-10-23 23:38:23,444 - DEBUG - VM ctest-TestRoutersBasic-05291428-95563729 launched on Node cn-jenkins-deploy-platform-ansible-os-4471-1
2025-10-23 23:38:23,526 - DEBUG - Requesting: http://10.0.0.242:8082/virtual-machine/103cd27a-d064-45fd-8986-98af87a8c50f
2025-10-23 23:38:23,537 - DEBUG - Requesting: http://10.0.0.242:8082/virtual-machine-interface/b7f0eb63-3e46-4e48-9a3e-065f3799273c
2025-10-23 23:38:24,783 - 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.54 ms\r\n64 bytes from 169.254.0.4: icmp_seq=2 ttl=63 time=3.05 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 = 3.054/3.294/3.535/0.240 ms')
2025-10-23 23:38:24,783 - INFO - Ping to Metadata IP 169.254.0.4 of VM ctest-TestRoutersBasic-05291428-95563729 passed
2025-10-23 23:38:24,944 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-23 23:38:24,944 - DEBUG - Waiting to SSH to VM ctest-TestRoutersBasic-05291428-95563729, IP 47.45.131.67, Port 22
2025-10-23 23:38:25,010 - DEBUG - Error on ssh to cirros@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': ''}
2025-10-23 23:38:25,103 - DEBUG - VM ctest-TestRoutersBasic-05291428-95563729 is NOT ready for SSH connections, VM status: ACTIVE
2025-10-23 23:38:30,103 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-23 23:38:30,103 - DEBUG - Waiting to SSH to VM ctest-TestRoutersBasic-05291428-95563729, IP 47.45.131.67, Port 22
2025-10-23 23:38:30,269 - DEBUG - VM ctest-TestRoutersBasic-05291428-95563729 is ready for SSH connections
2025-10-23 23:38:30,269 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-23 23:38:30,269 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 3 -W 1  47.45.131.67, host_string: cirros@169.254.0.3, password: cubswin:)gateway: ubuntu@10.0.0.242, gateway password: c0ntrail123
2025-10-23 23:38:30,270 - DEBUG - ping -s 56 -c 3 -W 1  47.45.131.67
2025-10-23 23:38:34,023 - DEBUG - PING 47.45.131.67 (47.45.131.67): 56 data bytes
64 bytes from 47.45.131.67: seq=0 ttl=62 time=8.078 ms
64 bytes from 47.45.131.67: seq=1 ttl=62 time=1.260 ms
64 bytes from 47.45.131.67: seq=2 ttl=62 time=1.007 ms
--- 47.45.131.67 ping statistics ---
3 packets transmitted, 3 packets received, 0% packet loss
round-trip min/avg/max = 1.007/3.448/8.078 ms
2025-10-23 23:38:34,023 - INFO - Ping to IP 47.45.131.67 from VM ctest-TestRoutersBasic-05291428-71542713 passed
2025-10-23 23:38:34,023 - INFO - Deleting interface with subnet_id 582235b5-7669-409a-a1c1-e35974d3bc06, port_id None from router 30e86fc6-3f29-4adc-bd79-955da88dab26
2025-10-23 23:38:34,292 - INFO - Deleting VM ctest-TestRoutersBasic-05291428-95563729
2025-10-23 23:38:34,399 - INFO - Deleting VM ctest-TestRoutersBasic-05291428-71542713
2025-10-23 23:38:34,517 - INFO - Deleting VN ctest-ext_vn-29314612 
2025-10-23 23:38:34,634 - DEBUG - VN f4b4f0f5-e953-404f-a7f5-fa65f7184206 still in use: Unable to complete operation on network f4b4f0f5-e953-404f-a7f5-fa65f7184206. There are one or more ports still in use on the network.
Neutron server returns request_ids: ['req-5595accf-7bc3-4b6c-a5b2-49e99061e336']
2025-10-23 23:38:34,635 - WARNING - Deleting VN ctest-ext_vn-29314612 failed..Will retry
2025-10-23 23:38:36,771 - DEBUG - Response for deleting network ()
2025-10-23 23:38:36,771 - INFO - Deleting VN ctest-vn-70373199 
2025-10-23 23:38:36,916 - DEBUG - Response for deleting network ()
2025-10-23 23:38:37,178 - DEBUG - No XMPP flaps were noticed during the test
2025-10-23 23:38:37,178 - INFO - END TEST : test_basic_snat_behavior_without_external_connectivity : PASSED[0:00:32]
2025-10-23 23:38:37,178 - INFO - --------------------------------------------------------------------------------
2025-10-23 23:38:37,958 - INFO - Deleted project: ctest-TestRoutersBasic-05291428, ID : 75d226e2-cf1b-4328-9cb9-ef6c87a2f152