is in ACTIVE state now
2025-08-06 07:42:16,108 - INFO - VM name : ctest-TestDSNAT-93951676-02199665
2025-08-06 07:42:16,234 - DEBUG - VM ctest-TestDSNAT-93951676-02199665 ID is 4a0ea980-153c-44c8-993d-c66914edd70c
2025-08-06 07:42:16,235 - DEBUG - VM ctest-TestDSNAT-93951676-02199665 launched on Node an-jenkins-deploy-platform-ansible-os-3761-2
2025-08-06 07:42:16,357 - DEBUG - Requesting: http://10.0.0.38:8082/virtual-machine/4a0ea980-153c-44c8-993d-c66914edd70c
2025-08-06 07:42:16,370 - DEBUG - Requesting: http://10.0.0.38:8082/virtual-machine-interface/173b3c22-d1a7-41d8-9914-11a86bfdd2b6
2025-08-06 07:42:17,650 - 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.81 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=2.03 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.034/3.423/4.813/1.389 ms')
2025-08-06 07:42:17,650 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-TestDSNAT-93951676-02199665 passed
2025-08-06 07:42:17,777 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-08-06 07:42:17,777 - DEBUG - Waiting to SSH to VM ctest-TestDSNAT-93951676-02199665, IP 26.230.31.196, Port 22
2025-08-06 07:42:17,948 - DEBUG - VM ctest-TestDSNAT-93951676-02199665 is ready for SSH connections
2025-08-06 07:42:18,111 - DEBUG - Fetched VN: default-domain:default-project:ip-fabric(b411f938-4e7b-428a-a093-d48a9100711c) with subnets None
2025-08-06 07:42:18,163 - DEBUG - Policy np_rules : [rule_sequence = None, rule_uuid = None, direction = <>, protocol = any, src_addresses = [subnet = None, virtual_network = default-domain:ctest-TestDSNAT-93951676:ctest-dsnat_vn-80057193, security_group = None, network_policy = None, subnet_list = []], src_ports = [start_port = -1, end_port = -1], application = [], dst_addresses = [subnet = None, virtual_network = default-domain:default-project:ip-fabric, security_group = None, network_policy = None, subnet_list = []], dst_ports = [start_port = -1, end_port = -1], action_list = simple_action = pass, gateway_name = None, apply_service = [], service_properties = None, mirror_to = None, assign_routing_instance = None, log = False, alert = False, qos_action = None, host_based_service = False, ethertype = None, created = None, last_modified = None, description = None]
2025-08-06 07:42:18,563 - INFO - Attaching policy ctest-test-dsnat-48722689 to vn ctest-dsnat_vn-80057193
2025-08-06 07:42:19,117 - INFO - Attaching policy ctest-test-dsnat-48722689 to vn ip-fabric
2025-08-06 07:42:19,387 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 3 -W 1 10.20.0.254, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.49, gateway password: c0ntrail123
2025-08-06 07:42:19,387 - DEBUG - ping -s 56 -c 3 -W 1 10.20.0.254
2025-08-06 07:42:40,678 - DEBUG - PING 10.20.0.254 (10.20.0.254) 56(84) bytes of data.
64 bytes from 10.20.0.254: icmp_req=1 ttl=62 time=2.43 ms
64 bytes from 10.20.0.254: icmp_req=2 ttl=62 time=1.72 ms
64 bytes from 10.20.0.254: icmp_req=3 ttl=62 time=0.832 ms
--- 10.20.0.254 ping statistics ---
3 packets transmitted, 3 received, 0% packet loss, time 2003ms
rtt min/avg/max/mdev = 0.832/1.663/2.433/0.656 ms
2025-08-06 07:42:40,679 - INFO - Ping to IP 10.20.0.254 from VM ctest-TestDSNAT-93951676-67839503 passed
2025-08-06 07:42:40,823 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 3 -W 1 10.20.0.254, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.49, gateway password: c0ntrail123
2025-08-06 07:42:40,823 - DEBUG - ping -s 56 -c 3 -W 1 10.20.0.254
2025-08-06 07:42:44,669 - DEBUG - PING 10.20.0.254 (10.20.0.254) 56(84) bytes of data.
--- 10.20.0.254 ping statistics ---
3 packets transmitted, 0 received, 100% packet loss, time 1999ms
2025-08-06 07:42:44,669 - WARNING - Ping to IP 10.20.0.254 from VM ctest-TestDSNAT-93951676-67839503 failed
2025-08-06 07:42:45,669 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 3 -W 1 10.20.0.254, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.49, gateway password: c0ntrail123
2025-08-06 07:42:45,670 - DEBUG - ping -s 56 -c 3 -W 1 10.20.0.254
2025-08-06 07:42:49,176 - DEBUG - PING 10.20.0.254 (10.20.0.254) 56(84) bytes of data.
--- 10.20.0.254 ping statistics ---
3 packets transmitted, 0 received, 100% packet loss, time 1999ms
2025-08-06 07:42:49,176 - WARNING - Ping to IP 10.20.0.254 from VM ctest-TestDSNAT-93951676-67839503 failed
2025-08-06 07:42:50,177 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 3 -W 1 10.20.0.254, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.49, gateway password: c0ntrail123
2025-08-06 07:42:50,177 - DEBUG - ping -s 56 -c 3 -W 1 10.20.0.254
2025-08-06 07:42:53,675 - DEBUG - PING 10.20.0.254 (10.20.0.254) 56(84) bytes of data.
--- 10.20.0.254 ping statistics ---
3 packets transmitted, 0 received, 100% packet loss, time 1999ms
2025-08-06 07:42:53,675 - WARNING - Ping to IP 10.20.0.254 from VM ctest-TestDSNAT-93951676-67839503 failed
2025-08-06 07:42:54,676 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 3 -W 1 10.20.0.254, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.49, gateway password: c0ntrail123
2025-08-06 07:42:54,676 - DEBUG - ping -s 56 -c 3 -W 1 10.20.0.254
2025-08-06 07:42:58,280 - DEBUG - PING 10.20.0.254 (10.20.0.254) 56(84) bytes of data.
--- 10.20.0.254 ping statistics ---
3 packets transmitted, 0 received, 100% packet loss, time 2000ms
2025-08-06 07:42:58,281 - WARNING - Ping to IP 10.20.0.254 from VM ctest-TestDSNAT-93951676-67839503 failed
2025-08-06 07:42:59,282 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 3 -W 1 10.20.0.254, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.49, gateway password: c0ntrail123
2025-08-06 07:42:59,282 - DEBUG - ping -s 56 -c 3 -W 1 10.20.0.254
2025-08-06 07:43:02,734 - DEBUG - PING 10.20.0.254 (10.20.0.254) 56(84) bytes of data.
--- 10.20.0.254 ping statistics ---
3 packets transmitted, 0 received, 100% packet loss, time 2015ms
2025-08-06 07:43:02,734 - WARNING - Ping to IP 10.20.0.254 from VM ctest-TestDSNAT-93951676-67839503 failed
2025-08-06 07:43:03,735 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 3 -W 1 10.20.0.254, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.49, gateway password: c0ntrail123
2025-08-06 07:43:03,736 - DEBUG - ping -s 56 -c 3 -W 1 10.20.0.254
2025-08-06 07:43:07,201 - DEBUG - PING 10.20.0.254 (10.20.0.254) 56(84) bytes of data.
--- 10.20.0.254 ping statistics ---
3 packets transmitted, 0 received, 100% packet loss, time 2017ms
2025-08-06 07:43:07,201 - WARNING - Ping to IP 10.20.0.254 from VM ctest-TestDSNAT-93951676-67839503 failed
2025-08-06 07:43:08,202 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 3 -W 1 10.20.0.254, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.49, gateway password: c0ntrail123
2025-08-06 07:43:08,202 - DEBUG - ping -s 56 -c 3 -W 1 10.20.0.254
2025-08-06 07:43:10,667 - DEBUG - PING 10.20.0.254 (10.20.0.254) 56(84) bytes of data.
64 bytes from 10.20.0.254: icmp_req=1 ttl=62 time=2.23 ms
64 bytes from 10.20.0.254: icmp_req=2 ttl=62 time=0.805 ms
64 bytes from 10.20.0.254: icmp_req=3 ttl=62 time=0.634 ms
--- 10.20.0.254 ping statistics ---
3 packets transmitted, 3 received, 0% packet loss, time 2004ms
rtt min/avg/max/mdev = 0.634/1.223/2.231/0.716 ms
2025-08-06 07:43:10,667 - INFO - Ping to IP 10.20.0.254 from VM ctest-TestDSNAT-93951676-67839503 passed
2025-08-06 07:43:10,667 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-08-06 07:43:10,667 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 3 -W 1 26.230.31.196, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.49, gateway password: c0ntrail123
2025-08-06 07:43:10,667 - DEBUG - ping -s 56 -c 3 -W 1 26.230.31.196
2025-08-06 07:43:13,190 - DEBUG - PING 26.230.31.196 (26.230.31.196) 56(84) bytes of data.
64 bytes from 26.230.31.196: icmp_req=1 ttl=63 time=12.5 ms
64 bytes from 26.230.31.196: icmp_req=2 ttl=63 time=2.10 ms
64 bytes from 26.230.31.196: icmp_req=3 ttl=63 time=1.43 ms
--- 26.230.31.196 ping statistics ---
3 packets transmitted, 3 received, 0% packet loss, time 2004ms
rtt min/avg/max/mdev = 1.432/5.367/12.568/5.099 ms
2025-08-06 07:43:13,190 - INFO - Ping to IP 26.230.31.196 from VM ctest-TestDSNAT-93951676-67839503 passed
2025-08-06 07:43:13,190 - INFO - Dettaching policy ctest-test-dsnat-48722689 from vn ip-fabric
2025-08-06 07:43:13,397 - INFO - Dettaching policy ctest-test-dsnat-48722689 from vn ctest-dsnat_vn-80057193
2025-08-06 07:43:13,642 - INFO - Deleted policy ctest-test-dsnat-48722689
2025-08-06 07:43:13,642 - INFO - Deleting VM ctest-TestDSNAT-93951676-02199665
2025-08-06 07:43:13,805 - INFO - Deleting VM ctest-TestDSNAT-93951676-67839503
2025-08-06 07:43:13,916 - INFO - Deleting VN ctest-dsnat_vn-80057193
2025-08-06 07:43:13,969 - DEBUG - VN 7eb8208a-116e-4e74-8967-af0ae59cf2ed still in use: Unable to complete operation on network 7eb8208a-116e-4e74-8967-af0ae59cf2ed. There are one or more ports still in use on the network.
Neutron server returns request_ids: ['req-72863e69-2138-46f9-b8c8-39b31c2b8a95']
2025-08-06 07:43:13,969 - WARNING - Deleting VN ctest-dsnat_vn-80057193 failed..Will retry
2025-08-06 07:43:16,205 - DEBUG - Response for deleting network ()
2025-08-06 07:43:17,502 - DEBUG - No XMPP flaps were noticed during the test
2025-08-06 07:43:17,502 - INFO - END TEST : test_dsnat_bug_1749695 : PASSED[0:03:31]
2025-08-06 07:43:17,502 - INFO - --------------------------------------------------------------------------------
2025-08-06 07:43:18,337 - INFO - Deleted project: ctest-TestDSNAT-93951676, ID : 9c25d4ce-06d7-40a0-94a0-249b7ece92a6
2025-08-06 09:48:26,297 - INFO - Domain Default found not creating
2025-08-06 09:48:26,713 - INFO - Project ctest-TestDSNAT-36030765 not found, creating it
2025-08-06 09:48:27,290 - INFO - Created Project:ctest-TestDSNAT-36030765, ID : 10101526-7735-428a-ad98-9d25fd799dc6
2025-08-06 09:48:29,336 - DEBUG - Services list from nova: [, , , ]
2025-08-06 09:48:29,336 - DEBUG - Hosts: {'nova': ['an-jenkins-deploy-platform-ansible-os-3761-1', 'an-jenkins-deploy-platform-ansible-os-3761-2']}
2025-08-06 09:48:29,336 - INFO - ================================================================================
2025-08-06 09:48:29,336 - INFO - STARTING TEST : test_dsnat_tcp_basic
2025-08-06 09:48:29,337 - INFO - TEST DESCRIPTION :
Configure TCP port translation pool
send TCP traffic from the VM to the fabric IP
Verify the Port address translation happened and the
port being used in the range of configured
2025-08-06 09:48:30,606 - DEBUG - Skipping xmpp flap check
2025-08-06 09:48:30,606 - INFO - Initial checks done. Running the testcase now
2025-08-06 09:48:30,606 - INFO -
2025-08-06 09:48:31,090 - INFO - Create VN, enable FABRIC SNAT and verify its routing instance
2025-08-06 09:48:31,519 - DEBUG - Response for create_network : {'network': {'id': '34e53f62-69cd-4550-a32b-86821277ed65', 'name': 'ctest-dsnat_vn-52026608', 'tenant_id': '101015267735428aad989d25fd799dc6', 'project_id': '101015267735428aad989d25fd799dc6', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': False, 'mtu': 0, 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestDSNAT-36030765', 'ctest-dsnat_vn-52026608'], 'port_security_enabled': True, 'description': ''}}
2025-08-06 09:48:31,868 - DEBUG - Response for create_subnet : {'subnet': {'id': 'a78be3fd-55d8-4a0e-bd6c-954b3c35c025', 'name': '', 'tenant_id': '101015267735428aad989d25fd799dc6', 'network_id': '34e53f62-69cd-4550-a32b-86821277ed65', 'ip_version': 4, 'cidr': '153.218.131.128/26', 'allocation_pools': [{'start': '153.218.131.130', 'end': '153.218.131.190'}], 'gateway_ip': '153.218.131.129', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '153.218.131.130', 'tags': [], 'project_id': '101015267735428aad989d25fd799dc6'}}
2025-08-06 09:48:31,896 - INFO - Created VN ctest-dsnat_vn-52026608
2025-08-06 09:48:31,911 - DEBUG - VN ctest-dsnat_vn-52026608 UUID is 34e53f62-69cd-4550-a32b-86821277ed65
2025-08-06 09:48:32,122 - DEBUG - Requesting: http://10.0.0.48:8082/virtual-network/34e53f62-69cd-4550-a32b-86821277ed65
2025-08-06 09:48:32,447 - DEBUG - Requesting: http://10.0.0.48:8082/virtual-network/34e53f62-69cd-4550-a32b-86821277ed65
2025-08-06 09:48:32,496 - DEBUG - Requesting: http://10.0.0.48:8082/routing-instance/b87761a8-5ff7-4272-ac5b-070d56da1262
2025-08-06 09:48:33,876 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-3761-1), Zone: (nova:an-jenkins-deploy-platform-ansible-os-3761-1)
2025-08-06 09:48:35,544 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-3761-2), Zone: (nova:an-jenkins-deploy-platform-ansible-os-3761-2)
2025-08-06 09:48:35,545 - INFO - Waiting for VM ctest-dsnat-vm1-08324268 to be up..
2025-08-06 09:48:35,646 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2025-08-06 09:48:40,748 - DEBUG - VM is in ACTIVE state now
2025-08-06 09:48:40,748 - INFO - VM name : ctest-dsnat-vm1-08324268
2025-08-06 09:48:40,844 - DEBUG - VM ctest-dsnat-vm1-08324268 ID is 74276bc4-4462-4012-b6ef-da5b53c7e29c
2025-08-06 09:48:40,875 - DEBUG - VM ctest-dsnat-vm1-08324268 launched on Node an-jenkins-deploy-platform-ansible-os-3761-1
2025-08-06 09:48:40,980 - DEBUG - Requesting: http://10.0.0.38:8082/virtual-machine/74276bc4-4462-4012-b6ef-da5b53c7e29c
2025-08-06 09:48:41,297 - DEBUG - Requesting: http://10.0.0.38:8082/virtual-machine/74276bc4-4462-4012-b6ef-da5b53c7e29c
2025-08-06 09:48:41,338 - DEBUG - Requesting: http://10.0.0.38:8082/virtual-machine-interface/004151cc-187f-499c-8ac1-f1d5be92d168
2025-08-06 09:48:44,536 - 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-08-06 09:48:44,536 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-08324268 failed!
2025-08-06 09:48:44,553 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-36030765:ctest-dsnat_vn-52026608 is 153.218.131.129 and allocation pool is NOT set
2025-08-06 09:48:48,637 - 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-08-06 09:48:48,637 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-08324268 failed!
2025-08-06 09:48:48,662 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-36030765:ctest-dsnat_vn-52026608 is 153.218.131.129 and allocation pool is NOT set
2025-08-06 09:48:52,737 - 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-08-06 09:48:52,738 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-08324268 failed!
2025-08-06 09:48:52,755 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-36030765:ctest-dsnat_vn-52026608 is 153.218.131.129 and allocation pool is NOT set
2025-08-06 09:48:56,829 - 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-08-06 09:48:56,829 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-08324268 failed!
2025-08-06 09:48:56,848 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-36030765:ctest-dsnat_vn-52026608 is 153.218.131.129 and allocation pool is NOT set
2025-08-06 09:49:00,927 - 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 1016ms')
2025-08-06 09:49:00,927 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-08324268 failed!
2025-08-06 09:49:00,948 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-36030765:ctest-dsnat_vn-52026608 is 153.218.131.129 and allocation pool is NOT set
2025-08-06 09:49:05,019 - 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')
2025-08-06 09:49:05,019 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-08324268 failed!
2025-08-06 09:49:05,039 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-36030765:ctest-dsnat_vn-52026608 is 153.218.131.129 and allocation pool is NOT set
2025-08-06 09:49:09,111 - 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 1014ms')
2025-08-06 09:49:09,111 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-08324268 failed!
2025-08-06 09:49:09,134 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-36030765:ctest-dsnat_vn-52026608 is 153.218.131.129 and allocation pool is NOT set
2025-08-06 09:49:11,206 - 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.64 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=2.43 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.430/3.534/4.639/1.104 ms')
2025-08-06 09:49:11,207 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-08324268 passed
2025-08-06 09:49:11,287 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-08-06 09:49:11,287 - DEBUG - Waiting to SSH to VM ctest-dsnat-vm1-08324268, IP 153.218.131.131, Port 22
2025-08-06 09:49:11,349 - 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-08-06 09:49:11,457 - DEBUG - VM ctest-dsnat-vm1-08324268 is NOT ready for SSH connections, VM status: ACTIVE
2025-08-06 09:49:16,458 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-08-06 09:49:16,458 - DEBUG - Waiting to SSH to VM ctest-dsnat-vm1-08324268, IP 153.218.131.131, Port 22
2025-08-06 09:49:16,520 - 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-08-06 09:49:16,616 - DEBUG - VM ctest-dsnat-vm1-08324268 is NOT ready for SSH connections, VM status: ACTIVE
2025-08-06 09:49:21,617 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-08-06 09:49:21,617 - DEBUG - Waiting to SSH to VM ctest-dsnat-vm1-08324268, IP 153.218.131.131, Port 22
2025-08-06 09:49:21,690 - 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-08-06 09:49:21,809 - DEBUG - VM ctest-dsnat-vm1-08324268 is NOT ready for SSH connections, VM status: ACTIVE
2025-08-06 09:49:26,810 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-08-06 09:49:26,810 - DEBUG - Waiting to SSH to VM ctest-dsnat-vm1-08324268, IP 153.218.131.131, Port 22
2025-08-06 09:49:26,968 - DEBUG - VM ctest-dsnat-vm1-08324268 is ready for SSH connections
2025-08-06 09:49:26,968 - INFO - Waiting for VM ctest-dsnat-vm2-91453156 to be up..
2025-08-06 09:49:27,079 - DEBUG - VM is in ACTIVE state now
2025-08-06 09:49:27,079 - INFO - VM name : ctest-dsnat-vm2-91453156
2025-08-06 09:49:27,196 - DEBUG - VM ctest-dsnat-vm2-91453156 ID is 02493fdf-31ae-4d33-8e7b-cd44e0532dfb
2025-08-06 09:49:27,196 - DEBUG - VM ctest-dsnat-vm2-91453156 launched on Node an-jenkins-deploy-platform-ansible-os-3761-2
2025-08-06 09:49:27,298 - DEBUG - Requesting: http://10.0.0.38:8082/virtual-machine/02493fdf-31ae-4d33-8e7b-cd44e0532dfb
2025-08-06 09:49:27,310 - DEBUG - Requesting: http://10.0.0.38:8082/virtual-machine-interface/c85aa36c-e5fa-46c7-b495-ea7f9ee0151b
2025-08-06 09:49:28,490 - 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.24 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=1.74 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.735/2.989/4.244/1.254 ms')
2025-08-06 09:49:28,490 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm2-91453156 passed
2025-08-06 09:49:28,567 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-08-06 09:49:28,567 - DEBUG - Waiting to SSH to VM ctest-dsnat-vm2-91453156, IP 153.218.131.132, Port 22
2025-08-06 09:49:28,633 - 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-08-06 09:49:28,737 - DEBUG - VM ctest-dsnat-vm2-91453156 is NOT ready for SSH connections, VM status: ACTIVE
2025-08-06 09:49:33,739 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-08-06 09:49:33,739 - DEBUG - Waiting to SSH to VM ctest-dsnat-vm2-91453156, IP 153.218.131.132, Port 22
2025-08-06 09:49:33,810 - 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-08-06 09:49:33,911 - DEBUG - VM ctest-dsnat-vm2-91453156 is NOT ready for SSH connections, VM status: ACTIVE
2025-08-06 09:49:38,912 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-08-06 09:49:38,912 - DEBUG - Waiting to SSH to VM ctest-dsnat-vm2-91453156, IP 153.218.131.132, Port 22
2025-08-06 09:49:39,093 - DEBUG - VM ctest-dsnat-vm2-91453156 is ready for SSH connections
2025-08-06 09:49:39,207 - DEBUG - command output is cat: /tmp/iperf_server_ctest-random-74107112.pid: No such file or directory
kill: usage: kill [-s sigspec | -n signum | -sigspec] pid | jobspec ... or kill -l [sigspec]
2025-08-06 09:49:39,324 - DEBUG - command output is
2025-08-06 09:49:39,324 - INFO - Starting Iperf3 on ctest-dsnat-vm1-08324268, args: --port 6201 --length 1048576 --time 10
2025-08-06 09:49:39,324 - DEBUG - Iperf3 cmd : iperf3 -c 10.20.0.129 --port 6201 --length 1048576 --time 10 1>/tmp/iper3_ctest-random-74107112.log 2>/tmp/iper3_ctest-random-74107112.result
2025-08-06 09:49:39,324 - INFO - Excecuting cmds, ['iperf3 -s --port 6201 1>/tmp/iper3_ctest-random-74107112.log 2>/tmp/iper3_ctest-random-74107112.result'], on server 10.0.0.57
2025-08-06 09:49:39,433 - DEBUG - command output is ['']
2025-08-06 09:49:39,433 - DEBUG - Running remote_cmd, Cmd : iperf3 -c 10.20.0.129 --port 6201 --length 1048576 --time 10 1>/tmp/iper3_ctest-random-74107112.log 2>/tmp/iper3_ctest-random-74107112.result, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.49, gateway password: c0ntrail123
2025-08-06 09:49:39,434 - DEBUG - nohup iperf3 -c 10.20.0.129 --port 6201 --length 1048576 --time 10 1>/tmp/iper3_ctest-random-74107112.log 2>/tmp/iper3_ctest-random-74107112.result & echo $! > /tmp/iperf_client_ctest-random-74107112.pid
2025-08-06 09:49:58,851 - ERROR - Exception occured while running cmds ['iperf3 -c 10.20.0.129 --port 6201 --length 1048576 --time 10 1>/tmp/iper3_ctest-random-74107112.log 2>/tmp/iper3_ctest-random-74107112.result']
2025-08-06 09:49:58,852 - ERROR - Timeout opening channel.
Traceback (most recent call last):
File "/contrail-test/tcutils/fabutils.py", line 169, in remote_cmd
output = _run(cmd, timeout=timeout, pty=not as_daemon, shell=shell)
File "/usr/local/lib/python3.6/site-packages/fabric/network.py", line 692, in host_prompting_wrapper
return func(*args, **kwargs)
File "/usr/local/lib/python3.6/site-packages/fabric/operations.py", line 1153, in sudo
capture_buffer_size=capture_buffer_size,
File "/usr/local/lib/python3.6/site-packages/fabric/operations.py", line 935, in _run_command
channel=default_channel(), command=wrapped_command, pty=pty,
File "/usr/local/lib/python3.6/site-packages/fabric/state.py", line 435, in default_channel
chan = _open_session()
File "/usr/local/lib/python3.6/site-packages/fabric/state.py", line 420, in _open_session
session = transport.open_session(timeout=env.timeout)
File "/usr/local/lib/python3.6/site-packages/paramiko/transport.py", line 923, in open_session
timeout=timeout,
File "/usr/local/lib/python3.6/site-packages/paramiko/transport.py", line 1050, in open_channel
raise e
File "/usr/local/lib/python3.6/site-packages/paramiko/transport.py", line 2109, in run
ptype, m = self.packetizer.read_message()
File "/usr/local/lib/python3.6/site-packages/paramiko/packet.py", line 459, in read_message
header = self.read_all(self.__block_size_in, check_rekey=True)
File "/usr/local/lib/python3.6/site-packages/paramiko/packet.py", line 303, in read_all
raise EOFError()
EOFError
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/usr/local/lib/python3.6/site-packages/fabric/state.py", line 435, in default_channel
chan = _open_session()
File "/usr/local/lib/python3.6/site-packages/fabric/state.py", line 420, in _open_session
session = transport.open_session(timeout=env.timeout)
File "/usr/local/lib/python3.6/site-packages/paramiko/transport.py", line 923, in open_session
timeout=timeout,
File "/usr/local/lib/python3.6/site-packages/paramiko/transport.py", line 1013, in open_channel
raise SSHException("SSH session not active")
paramiko.ssh_exception.SSHException: SSH session not active
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/contrail-test/fixtures/vm_test.py", line 2292, in run_cmd_on_vm
logger=self.logger
File "/contrail-test/tcutils/fabutils.py", line 178, in remote_cmd
output = _run(cmd, timeout=timeout, pty=not as_daemon, shell=shell)
File "/usr/local/lib/python3.6/site-packages/fabric/network.py", line 692, in host_prompting_wrapper
return func(*args, **kwargs)
File "/usr/local/lib/python3.6/site-packages/fabric/operations.py", line 1153, in sudo
capture_buffer_size=capture_buffer_size,
File "/usr/local/lib/python3.6/site-packages/fabric/operations.py", line 935, in _run_command
channel=default_channel(), command=wrapped_command, pty=pty,
File "/usr/local/lib/python3.6/site-packages/fabric/state.py", line 440, in default_channel
chan = _open_session()
File "/usr/local/lib/python3.6/site-packages/fabric/state.py", line 420, in _open_session
session = transport.open_session(timeout=env.timeout)
File "/usr/local/lib/python3.6/site-packages/paramiko/transport.py", line 923, in open_session
timeout=timeout,
File "/usr/local/lib/python3.6/site-packages/paramiko/transport.py", line 1054, in open_channel
raise SSHException("Timeout opening channel.")
paramiko.ssh_exception.SSHException: Timeout opening channel.
2025-08-06 09:50:02,018 - DEBUG - Returns multiple flows, [], matching flow data as list of tuples
2025-08-06 09:50:02,085 - DEBUG - command output is /bin/bash: line 1: kill: (66327) - No such process
2025-08-06 09:50:02,199 - DEBUG - command output is
2025-08-06 09:50:02,199 - INFO - Nat port being used for the flow is []
2025-08-06 09:50:07,279 - DEBUG - command output is /bin/bash: line 1: kill: (66327) - No such process
2025-08-06 09:50:07,391 - DEBUG - command output is
2025-08-06 09:50:07,391 - INFO - Starting Iperf3 on ctest-dsnat-vm1-08324268, args: --port 6201 --length 1048576 --time 10
2025-08-06 09:50:07,391 - DEBUG - Iperf3 cmd : iperf3 -c 10.20.0.129 --port 6201 --length 1048576 --time 10 1>/tmp/iper3_ctest-random-74107112.log 2>/tmp/iper3_ctest-random-74107112.result
2025-08-06 09:50:07,392 - INFO - Excecuting cmds, ['iperf3 -s --port 6201 1>/tmp/iper3_ctest-random-74107112.log 2>/tmp/iper3_ctest-random-74107112.result'], on server 10.0.0.57
2025-08-06 09:50:07,497 - DEBUG - command output is ['']
2025-08-06 09:50:07,497 - DEBUG - Running remote_cmd, Cmd : iperf3 -c 10.20.0.129 --port 6201 --length 1048576 --time 10 1>/tmp/iper3_ctest-random-74107112.log 2>/tmp/iper3_ctest-random-74107112.result, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.49, gateway password: c0ntrail123
2025-08-06 09:50:07,497 - DEBUG - nohup iperf3 -c 10.20.0.129 --port 6201 --length 1048576 --time 10 1>/tmp/iper3_ctest-random-74107112.log 2>/tmp/iper3_ctest-random-74107112.result & echo $! > /tmp/iperf_client_ctest-random-74107112.pid
2025-08-06 09:50:18,785 - DEBUG - None
2025-08-06 09:50:21,903 - DEBUG - Returns multiple flows, [], matching flow data as list of tuples
2025-08-06 09:50:21,973 - DEBUG - command output is /bin/bash: line 1: kill: (66459) - No such process
2025-08-06 09:50:22,091 - DEBUG - command output is
2025-08-06 09:50:22,091 - INFO - Nat port being used for the flow is []
2025-08-06 09:50:27,161 - DEBUG - command output is /bin/bash: line 1: kill: (66459) - No such process
2025-08-06 09:50:27,276 - DEBUG - command output is
2025-08-06 09:50:27,276 - INFO - Starting Iperf3 on ctest-dsnat-vm1-08324268, args: --port 6201 --length 1048576 --time 10
2025-08-06 09:50:27,276 - DEBUG - Iperf3 cmd : iperf3 -c 10.20.0.129 --port 6201 --length 1048576 --time 10 1>/tmp/iper3_ctest-random-74107112.log 2>/tmp/iper3_ctest-random-74107112.result
2025-08-06 09:50:27,276 - INFO - Excecuting cmds, ['iperf3 -s --port 6201 1>/tmp/iper3_ctest-random-74107112.log 2>/tmp/iper3_ctest-random-74107112.result'], on server 10.0.0.57
2025-08-06 09:50:27,377 - DEBUG - command output is ['']
2025-08-06 09:50:27,377 - DEBUG - Running remote_cmd, Cmd : iperf3 -c 10.20.0.129 --port 6201 --length 1048576 --time 10 1>/tmp/iper3_ctest-random-74107112.log 2>/tmp/iper3_ctest-random-74107112.result, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.49, gateway password: c0ntrail123
2025-08-06 09:50:27,377 - DEBUG - nohup iperf3 -c 10.20.0.129 --port 6201 --length 1048576 --time 10 1>/tmp/iper3_ctest-random-74107112.log 2>/tmp/iper3_ctest-random-74107112.result & echo $! > /tmp/iperf_client_ctest-random-74107112.pid
2025-08-06 09:50:27,765 - DEBUG - None
2025-08-06 09:50:30,898 - DEBUG - Returns multiple flows, [], matching flow data as list of tuples
2025-08-06 09:50:30,969 - DEBUG - command output is /bin/bash: line 1: kill: (66576) - No such process
2025-08-06 09:50:31,087 - DEBUG - command output is
2025-08-06 09:50:31,087 - INFO - Nat port being used for the flow is []
2025-08-06 09:50:36,158 - DEBUG - command output is /bin/bash: line 1: kill: (66576) - No such process
2025-08-06 09:50:36,276 - DEBUG - command output is
2025-08-06 09:50:36,276 - INFO - Starting Iperf3 on ctest-dsnat-vm1-08324268, args: --port 6201 --length 1048576 --time 10
2025-08-06 09:50:36,276 - DEBUG - Iperf3 cmd : iperf3 -c 10.20.0.129 --port 6201 --length 1048576 --time 10 1>/tmp/iper3_ctest-random-74107112.log 2>/tmp/iper3_ctest-random-74107112.result
2025-08-06 09:50:36,276 - INFO - Excecuting cmds, ['iperf3 -s --port 6201 1>/tmp/iper3_ctest-random-74107112.log 2>/tmp/iper3_ctest-random-74107112.result'], on server 10.0.0.57
2025-08-06 09:50:36,378 - DEBUG - command output is ['']
2025-08-06 09:50:36,378 - DEBUG - Running remote_cmd, Cmd : iperf3 -c 10.20.0.129 --port 6201 --length 1048576 --time 10 1>/tmp/iper3_ctest-random-74107112.log 2>/tmp/iper3_ctest-random-74107112.result, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.49, gateway password: c0ntrail123
2025-08-06 09:50:36,378 - DEBUG - nohup iperf3 -c 10.20.0.129 --port 6201 --length 1048576 --time 10 1>/tmp/iper3_ctest-random-74107112.log 2>/tmp/iper3_ctest-random-74107112.result & echo $! > /tmp/iperf_client_ctest-random-74107112.pid
2025-08-06 09:50:36,766 - DEBUG - None
2025-08-06 09:50:39,887 - DEBUG - Returns multiple flows, [], matching flow data as list of tuples
2025-08-06 09:50:39,968 - DEBUG - command output is /bin/bash: line 1: kill: (66679) - No such process
2025-08-06 09:50:40,075 - DEBUG - command output is
2025-08-06 09:50:40,075 - INFO - Nat port being used for the flow is []
2025-08-06 09:50:45,145 - DEBUG - command output is /bin/bash: line 1: kill: (66679) - No such process
2025-08-06 09:50:45,259 - DEBUG - command output is
2025-08-06 09:50:45,259 - INFO - Starting Iperf3 on ctest-dsnat-vm1-08324268, args: --port 6201 --length 1048576 --time 10
2025-08-06 09:50:45,260 - DEBUG - Iperf3 cmd : iperf3 -c 10.20.0.129 --port 6201 --length 1048576 --time 10 1>/tmp/iper3_ctest-random-74107112.log 2>/tmp/iper3_ctest-random-74107112.result
2025-08-06 09:50:45,260 - INFO - Excecuting cmds, ['iperf3 -s --port 6201 1>/tmp/iper3_ctest-random-74107112.log 2>/tmp/iper3_ctest-random-74107112.result'], on server 10.0.0.57
2025-08-06 09:50:45,361 - DEBUG - command output is ['']
2025-08-06 09:50:45,361 - DEBUG - Running remote_cmd, Cmd : iperf3 -c 10.20.0.129 --port 6201 --length 1048576 --time 10 1>/tmp/iper3_ctest-random-74107112.log 2>/tmp/iper3_ctest-random-74107112.result, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.49, gateway password: c0ntrail123
2025-08-06 09:50:45,361 - DEBUG - nohup iperf3 -c 10.20.0.129 --port 6201 --length 1048576 --time 10 1>/tmp/iper3_ctest-random-74107112.log 2>/tmp/iper3_ctest-random-74107112.result & echo $! > /tmp/iperf_client_ctest-random-74107112.pid
2025-08-06 09:50:45,763 - DEBUG - None
2025-08-06 09:50:48,889 - DEBUG - Returns multiple flows, [], matching flow data as list of tuples
2025-08-06 09:50:48,968 - DEBUG - command output is /bin/bash: line 1: kill: (66780) - No such process
2025-08-06 09:50:49,084 - DEBUG - command output is
2025-08-06 09:50:49,084 - INFO - Nat port being used for the flow is []
2025-08-06 09:50:54,159 - DEBUG - command output is /bin/bash: line 1: kill: (66780) - No such process
2025-08-06 09:50:54,275 - DEBUG - command output is
2025-08-06 09:50:54,275 - INFO - Starting Iperf3 on ctest-dsnat-vm1-08324268, args: --port 6201 --length 1048576 --time 10
2025-08-06 09:50:54,275 - DEBUG - Iperf3 cmd : iperf3 -c 10.20.0.129 --port 6201 --length 1048576 --time 10 1>/tmp/iper3_ctest-random-74107112.log 2>/tmp/iper3_ctest-random-74107112.result
2025-08-06 09:50:54,275 - INFO - Excecuting cmds, ['iperf3 -s --port 6201 1>/tmp/iper3_ctest-random-74107112.log 2>/tmp/iper3_ctest-random-74107112.result'], on server 10.0.0.57
2025-08-06 09:50:54,381 - DEBUG - command output is ['']
2025-08-06 09:50:54,381 - DEBUG - Running remote_cmd, Cmd : iperf3 -c 10.20.0.129 --port 6201 --length 1048576 --time 10 1>/tmp/iper3_ctest-random-74107112.log 2>/tmp/iper3_ctest-random-74107112.result, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.49, gateway password: c0ntrail123
2025-08-06 09:50:54,381 - DEBUG - nohup iperf3 -c 10.20.0.129 --port 6201 --length 1048576 --time 10 1>/tmp/iper3_ctest-random-74107112.log 2>/tmp/iper3_ctest-random-74107112.result & echo $! > /tmp/iperf_client_ctest-random-74107112.pid
2025-08-06 09:50:54,781 - DEBUG - None
2025-08-06 09:50:57,896 - DEBUG - Returns multiple flows, [], matching flow data as list of tuples
2025-08-06 09:50:57,965 - DEBUG - command output is /bin/bash: line 1: kill: (66853) - No such process
2025-08-06 09:50:58,083 - DEBUG - command output is
2025-08-06 09:50:58,083 - INFO - Nat port being used for the flow is []
2025-08-06 09:50:58,196 - DEBUG - command output is /bin/bash: line 1: kill: (66853) - No such process
2025-08-06 09:50:58,308 - DEBUG - command output is
2025-08-06 09:50:58,308 - INFO - Deleting VM ctest-dsnat-vm2-91453156
2025-08-06 09:50:58,421 - INFO - Deleting VM ctest-dsnat-vm1-08324268
2025-08-06 09:50:58,507 - INFO - Deleting VN ctest-dsnat_vn-52026608
2025-08-06 09:50:58,558 - DEBUG - VN 34e53f62-69cd-4550-a32b-86821277ed65 still in use: Unable to complete operation on network 34e53f62-69cd-4550-a32b-86821277ed65. There are one or more ports still in use on the network.
Neutron server returns request_ids: ['req-c5d481ad-352b-4216-b51d-41853db151ec']
2025-08-06 09:50:58,558 - WARNING - Deleting VN ctest-dsnat_vn-52026608 failed..Will retry
2025-08-06 09:51:00,832 - DEBUG - Response for deleting network ()
2025-08-06 09:51:02,115 - ERROR - AssertionError
Python 3.6.8: /usr/bin/python3
Wed Aug 6 09:50:58 2025
A problem occurred in a Python script. Here is the sequence of
function calls leading up to the error, in the order they occurred.
/contrail-test/tcutils/wrappers.py in wrapper(self=, *args=(), **kwargs={})
78 log.info('Initial checks done. Running the testcase now')
79 log.info('')
80 result = function(self, *args, **kwargs)
81 if self.inputs.upgrade:
82 pid = os.getpid()
result = None
function =
self =
args = ()
kwargs = {}
/contrail-test/serial_scripts/dsnat/test_dsnat.py in test_dsnat_tcp_basic(self=)
109 self.iperf = None
110
111 assert self.verify_flow_with_port(vm1_fixture, vm2_fixture, port_range, **traffic)
112
113 @preposttest_wrapper
self =
self.verify_flow_with_port = .deco_retry.....test_dsnat_tcp_basic[sanity] id=0x7f8cd79c5710>>
vm1_fixture =
vm2_fixture =
port_range = [65000, 65001, 65002, 65003, 65004, 65005, 65006, 65007, 65008, 65009]
traffic = {'port': 6201, 'udp': False}
AssertionError:
__cause__ = None
__class__ =
__context__ = None
__delattr__ =
__dict__ = {}
__dir__ =
__doc__ = 'Assertion failed.'
__eq__ =
__format__ =
__ge__ =
__getattribute__ =
__gt__ =
__hash__ =
__init__ =
__init_subclass__ =
__le__ =
__lt__ =
__ne__ =
__new__ =
__reduce__ =
__reduce_ex__ =
__repr__ =
__setattr__ =
__setstate__ =
__sizeof__ =
__str__ =
__subclasshook__ =
__suppress_context__ = False
__traceback__ =
args = ()
with_traceback =
The above is a description of an error in a Python program. Here is
the original traceback:
Traceback (most recent call last):
File "/contrail-test/tcutils/wrappers.py", line 80, in wrapper
result = function(self, *args, **kwargs)
File "/contrail-test/serial_scripts/dsnat/test_dsnat.py", line 111, in test_dsnat_tcp_basic
assert self.verify_flow_with_port(vm1_fixture, vm2_fixture, port_range, **traffic)
AssertionError
2025-08-06 09:51:02,115 - DEBUG - Skipping xmpp flap check
2025-08-06 09:51:02,115 - INFO -
2025-08-06 09:51:02,115 - INFO - END TEST : test_dsnat_tcp_basic : FAILED[0:02:33]
2025-08-06 09:51:02,115 - INFO - --------------------------------------------------------------------------------
2025-08-06 09:51:02,120 - DEBUG - Hosts: {'nova': ['an-jenkins-deploy-platform-ansible-os-3761-1', 'an-jenkins-deploy-platform-ansible-os-3761-2']}
2025-08-06 09:51:02,120 - INFO - ================================================================================
2025-08-06 09:51:02,121 - INFO - STARTING TEST : test_dsnat_udp_basic
2025-08-06 09:51:02,121 - INFO - TEST DESCRIPTION :
configure port translation pools in the global vrouter config
create a test VN , enable SNAT,
send UDP traffic from VM to fabric IP and verify the PAT happened,
and the port been used in the range
2025-08-06 09:51:03,411 - DEBUG - Skipping xmpp flap check
2025-08-06 09:51:03,411 - INFO - Initial checks done. Running the testcase now
2025-08-06 09:51:03,411 - INFO -
2025-08-06 09:51:03,411 - INFO - configure port translation pool in global vrouter config for both TCP and UDP in the range of 65000 to 65009
2025-08-06 09:51:03,502 - INFO - Create VN, enable FABRIC SNAT and verify its routing instance
2025-08-06 09:51:03,914 - DEBUG - Response for create_network : {'network': {'id': 'b19e0c1d-f727-4c4d-9fa3-190c6c10b68b', 'name': 'ctest-dsnat_vn-43004073', 'tenant_id': '101015267735428aad989d25fd799dc6', 'project_id': '101015267735428aad989d25fd799dc6', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': False, 'mtu': 0, 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestDSNAT-36030765', 'ctest-dsnat_vn-43004073'], 'port_security_enabled': True, 'description': ''}}
2025-08-06 09:51:04,180 - DEBUG - Response for create_subnet : {'subnet': {'id': '64849b46-4cad-471a-9b57-2beb6dc7eb4a', 'name': '', 'tenant_id': '101015267735428aad989d25fd799dc6', 'network_id': 'b19e0c1d-f727-4c4d-9fa3-190c6c10b68b', 'ip_version': 4, 'cidr': '166.37.116.64/26', 'allocation_pools': [{'start': '166.37.116.66', 'end': '166.37.116.126'}], 'gateway_ip': '166.37.116.65', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '166.37.116.66', 'tags': [], 'project_id': '101015267735428aad989d25fd799dc6'}}
2025-08-06 09:51:04,208 - INFO - Created VN ctest-dsnat_vn-43004073
2025-08-06 09:51:04,223 - DEBUG - VN ctest-dsnat_vn-43004073 UUID is b19e0c1d-f727-4c4d-9fa3-190c6c10b68b
2025-08-06 09:51:04,519 - DEBUG - Requesting: http://10.0.0.48:8082/virtual-network/b19e0c1d-f727-4c4d-9fa3-190c6c10b68b
2025-08-06 09:51:04,536 - DEBUG - Requesting: http://10.0.0.48:8082/routing-instance/14a28eef-48ec-417e-8724-846aa0c4b543
2025-08-06 09:51:05,934 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-3761-1), Zone: (nova:an-jenkins-deploy-platform-ansible-os-3761-1)
2025-08-06 09:51:07,500 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-3761-2), Zone: (nova:an-jenkins-deploy-platform-ansible-os-3761-2)
2025-08-06 09:51:07,500 - INFO - Waiting for VM ctest-dsnat-vm1-87898512 to be up..
2025-08-06 09:51:07,600 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2025-08-06 09:51:12,711 - DEBUG - VM is in ACTIVE state now
2025-08-06 09:51:12,711 - INFO - VM name : ctest-dsnat-vm1-87898512
2025-08-06 09:51:12,823 - DEBUG - VM ctest-dsnat-vm1-87898512 ID is fe7bec29-9e1e-4850-8931-417fa204c7f9
2025-08-06 09:51:12,823 - DEBUG - VM ctest-dsnat-vm1-87898512 launched on Node an-jenkins-deploy-platform-ansible-os-3761-1
2025-08-06 09:51:12,933 - DEBUG - Requesting: http://10.0.0.38:8082/virtual-machine/fe7bec29-9e1e-4850-8931-417fa204c7f9
2025-08-06 09:51:12,948 - DEBUG - Requesting: http://10.0.0.38:8082/virtual-machine-interface/6bfdca29-96a7-4435-aabb-16bae5caf4a9
2025-08-06 09:51:16,160 - 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 1032ms')
2025-08-06 09:51:16,160 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-87898512 failed!
2025-08-06 09:51:16,181 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-36030765:ctest-dsnat_vn-43004073 is 166.37.116.65 and allocation pool is NOT set
2025-08-06 09:51:20,255 - 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')
2025-08-06 09:51:20,255 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-87898512 failed!
2025-08-06 09:51:20,275 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-36030765:ctest-dsnat_vn-43004073 is 166.37.116.65 and allocation pool is NOT set
2025-08-06 09:51:24,346 - 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-08-06 09:51:24,346 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-87898512 failed!
2025-08-06 09:51:24,368 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-36030765:ctest-dsnat_vn-43004073 is 166.37.116.65 and allocation pool is NOT set
2025-08-06 09:51:28,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 1011ms')
2025-08-06 09:51:28,441 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-87898512 failed!
2025-08-06 09:51:28,476 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-36030765:ctest-dsnat_vn-43004073 is 166.37.116.65 and allocation pool is NOT set
2025-08-06 09:51:32,572 - 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 1029ms')
2025-08-06 09:51:32,572 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-87898512 failed!
2025-08-06 09:51:32,590 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-36030765:ctest-dsnat_vn-43004073 is 166.37.116.65 and allocation pool is NOT set
2025-08-06 09:51:36,662 - 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-08-06 09:51:36,662 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-87898512 failed!
2025-08-06 09:51:36,679 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-36030765:ctest-dsnat_vn-43004073 is 166.37.116.65 and allocation pool is NOT set
2025-08-06 09:51:40,765 - 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 1016ms')
2025-08-06 09:51:40,765 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-87898512 failed!
2025-08-06 09:51:40,781 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-36030765:ctest-dsnat_vn-43004073 is 166.37.116.65 and allocation pool is NOT set
2025-08-06 09:51:42,845 - 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.65 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=3.87 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 = 3.871/4.761/5.652/0.890 ms')
2025-08-06 09:51:42,846 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-87898512 passed
2025-08-06 09:51:42,934 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-08-06 09:51:42,934 - DEBUG - Waiting to SSH to VM ctest-dsnat-vm1-87898512, IP 166.37.116.67, Port 22
2025-08-06 09:51:43,007 - 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-08-06 09:51:43,128 - DEBUG - VM ctest-dsnat-vm1-87898512 is NOT ready for SSH connections, VM status: ACTIVE
2025-08-06 09:51:48,129 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-08-06 09:51:48,130 - DEBUG - Waiting to SSH to VM ctest-dsnat-vm1-87898512, IP 166.37.116.67, Port 22
2025-08-06 09:51:48,188 - 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-08-06 09:51:48,291 - DEBUG - VM ctest-dsnat-vm1-87898512 is NOT ready for SSH connections, VM status: ACTIVE
2025-08-06 09:51:53,291 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-08-06 09:51:53,292 - DEBUG - Waiting to SSH to VM ctest-dsnat-vm1-87898512, IP 166.37.116.67, Port 22
2025-08-06 09:51:53,358 - 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-08-06 09:51:53,469 - DEBUG - VM ctest-dsnat-vm1-87898512 is NOT ready for SSH connections, VM status: ACTIVE
2025-08-06 09:51:58,470 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-08-06 09:51:58,470 - DEBUG - Waiting to SSH to VM ctest-dsnat-vm1-87898512, IP 166.37.116.67, Port 22
2025-08-06 09:51:58,529 - 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-08-06 09:51:58,641 - DEBUG - VM ctest-dsnat-vm1-87898512 is NOT ready for SSH connections, VM status: ACTIVE
2025-08-06 09:52:03,642 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-08-06 09:52:03,642 - DEBUG - Waiting to SSH to VM ctest-dsnat-vm1-87898512, IP 166.37.116.67, Port 22
2025-08-06 09:52:03,811 - DEBUG - VM ctest-dsnat-vm1-87898512 is ready for SSH connections
2025-08-06 09:52:03,811 - INFO - Waiting for VM ctest-dsnat-vm2-19060146 to be up..
2025-08-06 09:52:03,903 - DEBUG - VM is in ACTIVE state now
2025-08-06 09:52:03,903 - INFO - VM name : ctest-dsnat-vm2-19060146
2025-08-06 09:52:03,996 - DEBUG - VM ctest-dsnat-vm2-19060146 ID is f24d4c66-bd01-44d2-8252-0420b7181dc1
2025-08-06 09:52:03,996 - DEBUG - VM ctest-dsnat-vm2-19060146 launched on Node an-jenkins-deploy-platform-ansible-os-3761-2
2025-08-06 09:52:04,102 - DEBUG - Requesting: http://10.0.0.38:8082/virtual-machine/f24d4c66-bd01-44d2-8252-0420b7181dc1
2025-08-06 09:52:04,113 - DEBUG - Requesting: http://10.0.0.38:8082/virtual-machine-interface/91f53b29-ea3b-48ef-aade-e2b87074743d
2025-08-06 09:52:05,292 - 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=6.91 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=2.88 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.878/4.894/6.911/2.016 ms')
2025-08-06 09:52:05,293 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm2-19060146 passed
2025-08-06 09:52:05,370 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-08-06 09:52:05,370 - DEBUG - Waiting to SSH to VM ctest-dsnat-vm2-19060146, IP 166.37.116.68, Port 22
2025-08-06 09:52:05,436 - 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-08-06 09:52:05,519 - DEBUG - VM ctest-dsnat-vm2-19060146 is NOT ready for SSH connections, VM status: ACTIVE
2025-08-06 09:52:10,520 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-08-06 09:52:10,520 - DEBUG - Waiting to SSH to VM ctest-dsnat-vm2-19060146, IP 166.37.116.68, Port 22
2025-08-06 09:52:10,684 - DEBUG - VM ctest-dsnat-vm2-19060146 is ready for SSH connections
2025-08-06 09:52:10,793 - DEBUG - command output is cat: /tmp/iperf_server_ctest-random-09493396.pid: No such file or directory
kill: usage: kill [-s sigspec | -n signum | -sigspec] pid | jobspec ... or kill -l [sigspec]
2025-08-06 09:52:10,907 - DEBUG - command output is
2025-08-06 09:52:10,907 - INFO - Starting Iperf3 on ctest-dsnat-vm1-87898512, args: --port 5201 --udp --length 65507 --time 10
2025-08-06 09:52:10,907 - DEBUG - Iperf3 cmd : iperf3 -c 10.20.0.129 --port 5201 --udp --length 65507 --time 10 1>/tmp/iper3_ctest-random-09493396.log 2>/tmp/iper3_ctest-random-09493396.result
2025-08-06 09:52:10,907 - INFO - Excecuting cmds, ['iperf3 -s --port 5201 1>/tmp/iper3_ctest-random-09493396.log 2>/tmp/iper3_ctest-random-09493396.result'], on server 10.0.0.57
2025-08-06 09:52:11,014 - DEBUG - command output is ['']
2025-08-06 09:52:11,014 - DEBUG - Running remote_cmd, Cmd : iperf3 -c 10.20.0.129 --port 5201 --udp --length 65507 --time 10 1>/tmp/iper3_ctest-random-09493396.log 2>/tmp/iper3_ctest-random-09493396.result, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.49, gateway password: c0ntrail123
2025-08-06 09:52:11,014 - DEBUG - nohup iperf3 -c 10.20.0.129 --port 5201 --udp --length 65507 --time 10 1>/tmp/iper3_ctest-random-09493396.log 2>/tmp/iper3_ctest-random-09493396.result & echo $! > /tmp/iperf_client_ctest-random-09493396.pid
2025-08-06 09:52:28,950 - ERROR - Exception occured while running cmds ['iperf3 -c 10.20.0.129 --port 5201 --udp --length 65507 --time 10 1>/tmp/iper3_ctest-random-09493396.log 2>/tmp/iper3_ctest-random-09493396.result']
2025-08-06 09:52:28,950 - ERROR - Timeout opening channel.
Traceback (most recent call last):
File "/contrail-test/tcutils/fabutils.py", line 169, in remote_cmd
output = _run(cmd, timeout=timeout, pty=not as_daemon, shell=shell)
File "/usr/local/lib/python3.6/site-packages/fabric/network.py", line 692, in host_prompting_wrapper
return func(*args, **kwargs)
File "/usr/local/lib/python3.6/site-packages/fabric/operations.py", line 1153, in sudo
capture_buffer_size=capture_buffer_size,
File "/usr/local/lib/python3.6/site-packages/fabric/operations.py", line 935, in _run_command
channel=default_channel(), command=wrapped_command, pty=pty,
File "/usr/local/lib/python3.6/site-packages/fabric/state.py", line 435, in default_channel
chan = _open_session()
File "/usr/local/lib/python3.6/site-packages/fabric/state.py", line 420, in _open_session
session = transport.open_session(timeout=env.timeout)
File "/usr/local/lib/python3.6/site-packages/paramiko/transport.py", line 923, in open_session
timeout=timeout,
File "/usr/local/lib/python3.6/site-packages/paramiko/transport.py", line 1050, in open_channel
raise e
File "/usr/local/lib/python3.6/site-packages/paramiko/transport.py", line 2109, in run
ptype, m = self.packetizer.read_message()
File "/usr/local/lib/python3.6/site-packages/paramiko/packet.py", line 459, in read_message
header = self.read_all(self.__block_size_in, check_rekey=True)
File "/usr/local/lib/python3.6/site-packages/paramiko/packet.py", line 303, in read_all
raise EOFError()
EOFError
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/usr/local/lib/python3.6/site-packages/fabric/state.py", line 435, in default_channel
chan = _open_session()
File "/usr/local/lib/python3.6/site-packages/fabric/state.py", line 420, in _open_session
session = transport.open_session(timeout=env.timeout)
File "/usr/local/lib/python3.6/site-packages/paramiko/transport.py", line 923, in open_session
timeout=timeout,
File "/usr/local/lib/python3.6/site-packages/paramiko/transport.py", line 1013, in open_channel
raise SSHException("SSH session not active")
paramiko.ssh_exception.SSHException: SSH session not active
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/contrail-test/fixtures/vm_test.py", line 2292, in run_cmd_on_vm
logger=self.logger
File "/contrail-test/tcutils/fabutils.py", line 178, in remote_cmd
output = _run(cmd, timeout=timeout, pty=not as_daemon, shell=shell)
File "/usr/local/lib/python3.6/site-packages/fabric/network.py", line 692, in host_prompting_wrapper
return func(*args, **kwargs)
File "/usr/local/lib/python3.6/site-packages/fabric/operations.py", line 1153, in sudo
capture_buffer_size=capture_buffer_size,
File "/usr/local/lib/python3.6/site-packages/fabric/operations.py", line 935, in _run_command
channel=default_channel(), command=wrapped_command, pty=pty,
File "/usr/local/lib/python3.6/site-packages/fabric/state.py", line 440, in default_channel
chan = _open_session()
File "/usr/local/lib/python3.6/site-packages/fabric/state.py", line 420, in _open_session
session = transport.open_session(timeout=env.timeout)
File "/usr/local/lib/python3.6/site-packages/paramiko/transport.py", line 923, in open_session
timeout=timeout,
File "/usr/local/lib/python3.6/site-packages/paramiko/transport.py", line 1054, in open_channel
raise SSHException("Timeout opening channel.")
paramiko.ssh_exception.SSHException: Timeout opening channel.
2025-08-06 09:52:32,107 - DEBUG - Returns multiple flows, [], matching flow data as list of tuples
2025-08-06 09:52:32,177 - DEBUG - command output is /bin/bash: line 1: kill: (67258) - No such process
2025-08-06 09:52:32,290 - DEBUG - command output is
2025-08-06 09:52:32,291 - INFO - Nat port being used for the flow is []
2025-08-06 09:52:37,362 - DEBUG - command output is /bin/bash: line 1: kill: (67258) - No such process
2025-08-06 09:52:37,480 - DEBUG - command output is
2025-08-06 09:52:37,480 - INFO - Starting Iperf3 on ctest-dsnat-vm1-87898512, args: --port 5201 --udp --length 65507 --time 10
2025-08-06 09:52:37,480 - DEBUG - Iperf3 cmd : iperf3 -c 10.20.0.129 --port 5201 --udp --length 65507 --time 10 1>/tmp/iper3_ctest-random-09493396.log 2>/tmp/iper3_ctest-random-09493396.result
2025-08-06 09:52:37,480 - INFO - Excecuting cmds, ['iperf3 -s --port 5201 1>/tmp/iper3_ctest-random-09493396.log 2>/tmp/iper3_ctest-random-09493396.result'], on server 10.0.0.57
2025-08-06 09:52:37,581 - DEBUG - command output is ['']
2025-08-06 09:52:37,581 - DEBUG - Running remote_cmd, Cmd : iperf3 -c 10.20.0.129 --port 5201 --udp --length 65507 --time 10 1>/tmp/iper3_ctest-random-09493396.log 2>/tmp/iper3_ctest-random-09493396.result, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.49, gateway password: c0ntrail123
2025-08-06 09:52:37,581 - DEBUG - nohup iperf3 -c 10.20.0.129 --port 5201 --udp --length 65507 --time 10 1>/tmp/iper3_ctest-random-09493396.log 2>/tmp/iper3_ctest-random-09493396.result & echo $! > /tmp/iperf_client_ctest-random-09493396.pid
2025-08-06 09:52:52,278 - DEBUG - None
2025-08-06 09:52:55,420 - DEBUG - Returns multiple flows, [], matching flow data as list of tuples
2025-08-06 09:52:55,488 - DEBUG - command output is /bin/bash: line 1: kill: (67373) - No such process
2025-08-06 09:52:55,608 - DEBUG - command output is
2025-08-06 09:52:55,608 - INFO - Nat port being used for the flow is []
2025-08-06 09:53:00,677 - DEBUG - command output is /bin/bash: line 1: kill: (67373) - No such process
2025-08-06 09:53:00,796 - DEBUG - command output is
2025-08-06 09:53:00,796 - INFO - Starting Iperf3 on ctest-dsnat-vm1-87898512, args: --port 5201 --udp --length 65507 --time 10
2025-08-06 09:53:00,797 - DEBUG - Iperf3 cmd : iperf3 -c 10.20.0.129 --port 5201 --udp --length 65507 --time 10 1>/tmp/iper3_ctest-random-09493396.log 2>/tmp/iper3_ctest-random-09493396.result
2025-08-06 09:53:00,797 - INFO - Excecuting cmds, ['iperf3 -s --port 5201 1>/tmp/iper3_ctest-random-09493396.log 2>/tmp/iper3_ctest-random-09493396.result'], on server 10.0.0.57
2025-08-06 09:53:00,906 - DEBUG - command output is ['']
2025-08-06 09:53:00,906 - DEBUG - Running remote_cmd, Cmd : iperf3 -c 10.20.0.129 --port 5201 --udp --length 65507 --time 10 1>/tmp/iper3_ctest-random-09493396.log 2>/tmp/iper3_ctest-random-09493396.result, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.49, gateway password: c0ntrail123
2025-08-06 09:53:00,906 - DEBUG - nohup iperf3 -c 10.20.0.129 --port 5201 --udp --length 65507 --time 10 1>/tmp/iper3_ctest-random-09493396.log 2>/tmp/iper3_ctest-random-09493396.result & echo $! > /tmp/iperf_client_ctest-random-09493396.pid
2025-08-06 09:53:01,324 - DEBUG - None
2025-08-06 09:53:04,460 - DEBUG - Returns multiple flows, [], matching flow data as list of tuples
2025-08-06 09:53:04,529 - DEBUG - command output is /bin/bash: line 1: kill: (67570) - No such process
2025-08-06 09:53:04,648 - DEBUG - command output is
2025-08-06 09:53:04,648 - INFO - Nat port being used for the flow is []
2025-08-06 09:53:09,728 - DEBUG - command output is /bin/bash: line 1: kill: (67570) - No such process
2025-08-06 09:53:09,844 - DEBUG - command output is
2025-08-06 09:53:09,844 - INFO - Starting Iperf3 on ctest-dsnat-vm1-87898512, args: --port 5201 --udp --length 65507 --time 10
2025-08-06 09:53:09,844 - DEBUG - Iperf3 cmd : iperf3 -c 10.20.0.129 --port 5201 --udp --length 65507 --time 10 1>/tmp/iper3_ctest-random-09493396.log 2>/tmp/iper3_ctest-random-09493396.result
2025-08-06 09:53:09,844 - INFO - Excecuting cmds, ['iperf3 -s --port 5201 1>/tmp/iper3_ctest-random-09493396.log 2>/tmp/iper3_ctest-random-09493396.result'], on server 10.0.0.57
2025-08-06 09:53:09,949 - DEBUG - command output is ['']
2025-08-06 09:53:09,949 - DEBUG - Running remote_cmd, Cmd : iperf3 -c 10.20.0.129 --port 5201 --udp --length 65507 --time 10 1>/tmp/iper3_ctest-random-09493396.log 2>/tmp/iper3_ctest-random-09493396.result, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.49, gateway password: c0ntrail123
2025-08-06 09:53:09,949 - DEBUG - nohup iperf3 -c 10.20.0.129 --port 5201 --udp --length 65507 --time 10 1>/tmp/iper3_ctest-random-09493396.log 2>/tmp/iper3_ctest-random-09493396.result & echo $! > /tmp/iperf_client_ctest-random-09493396.pid
2025-08-06 09:53:10,327 - DEBUG - None
2025-08-06 09:53:13,457 - DEBUG - Returns multiple flows, [], matching flow data as list of tuples
2025-08-06 09:53:13,535 - DEBUG - command output is /bin/bash: line 1: kill: (67619) - No such process
2025-08-06 09:53:13,643 - DEBUG - command output is
2025-08-06 09:53:13,643 - INFO - Nat port being used for the flow is []
2025-08-06 09:53:18,713 - DEBUG - command output is /bin/bash: line 1: kill: (67619) - No such process
2025-08-06 09:53:18,831 - DEBUG - command output is
2025-08-06 09:53:18,831 - INFO - Starting Iperf3 on ctest-dsnat-vm1-87898512, args: --port 5201 --udp --length 65507 --time 10
2025-08-06 09:53:18,831 - DEBUG - Iperf3 cmd : iperf3 -c 10.20.0.129 --port 5201 --udp --length 65507 --time 10 1>/tmp/iper3_ctest-random-09493396.log 2>/tmp/iper3_ctest-random-09493396.result
2025-08-06 09:53:18,831 - INFO - Excecuting cmds, ['iperf3 -s --port 5201 1>/tmp/iper3_ctest-random-09493396.log 2>/tmp/iper3_ctest-random-09493396.result'], on server 10.0.0.57
2025-08-06 09:53:18,937 - DEBUG - command output is ['']
2025-08-06 09:53:18,937 - DEBUG - Running remote_cmd, Cmd : iperf3 -c 10.20.0.129 --port 5201 --udp --length 65507 --time 10 1>/tmp/iper3_ctest-random-09493396.log 2>/tmp/iper3_ctest-random-09493396.result, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.49, gateway password: c0ntrail123
2025-08-06 09:53:18,937 - DEBUG - nohup iperf3 -c 10.20.0.129 --port 5201 --udp --length 65507 --time 10 1>/tmp/iper3_ctest-random-09493396.log 2>/tmp/iper3_ctest-random-09493396.result & echo $! > /tmp/iperf_client_ctest-random-09493396.pid
2025-08-06 09:53:19,346 - DEBUG - None
2025-08-06 09:53:22,484 - DEBUG - Returns multiple flows, [], matching flow data as list of tuples
2025-08-06 09:53:22,552 - DEBUG - command output is /bin/bash: line 1: kill: (67700) - No such process
2025-08-06 09:53:22,672 - DEBUG - command output is
2025-08-06 09:53:22,672 - INFO - Nat port being used for the flow is []
2025-08-06 09:53:27,752 - DEBUG - command output is /bin/bash: line 1: kill: (67700) - No such process
2025-08-06 09:53:27,860 - DEBUG - command output is
2025-08-06 09:53:27,860 - INFO - Starting Iperf3 on ctest-dsnat-vm1-87898512, args: --port 5201 --udp --length 65507 --time 10
2025-08-06 09:53:27,860 - DEBUG - Iperf3 cmd : iperf3 -c 10.20.0.129 --port 5201 --udp --length 65507 --time 10 1>/tmp/iper3_ctest-random-09493396.log 2>/tmp/iper3_ctest-random-09493396.result
2025-08-06 09:53:27,860 - INFO - Excecuting cmds, ['iperf3 -s --port 5201 1>/tmp/iper3_ctest-random-09493396.log 2>/tmp/iper3_ctest-random-09493396.result'], on server 10.0.0.57
2025-08-06 09:53:27,971 - DEBUG - command output is ['']
2025-08-06 09:53:27,971 - DEBUG - Running remote_cmd, Cmd : iperf3 -c 10.20.0.129 --port 5201 --udp --length 65507 --time 10 1>/tmp/iper3_ctest-random-09493396.log 2>/tmp/iper3_ctest-random-09493396.result, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.49, gateway password: c0ntrail123
2025-08-06 09:53:27,971 - DEBUG - nohup iperf3 -c 10.20.0.129 --port 5201 --udp --length 65507 --time 10 1>/tmp/iper3_ctest-random-09493396.log 2>/tmp/iper3_ctest-random-09493396.result & echo $! > /tmp/iperf_client_ctest-random-09493396.pid
2025-08-06 09:53:28,371 - DEBUG - None
2025-08-06 09:53:31,517 - DEBUG - Returns multiple flows, [], matching flow data as list of tuples
2025-08-06 09:53:31,596 - DEBUG - command output is /bin/bash: line 1: kill: (67762) - No such process
2025-08-06 09:53:31,707 - DEBUG - command output is
2025-08-06 09:53:31,708 - INFO - Nat port being used for the flow is []
2025-08-06 09:53:31,810 - DEBUG - command output is /bin/bash: line 1: kill: (67762) - No such process
2025-08-06 09:53:31,930 - DEBUG - command output is
2025-08-06 09:53:31,930 - INFO - Deleting VM ctest-dsnat-vm2-19060146
2025-08-06 09:53:32,066 - INFO - Deleting VM ctest-dsnat-vm1-87898512
2025-08-06 09:53:32,149 - INFO - Deleting VN ctest-dsnat_vn-43004073
2025-08-06 09:53:32,252 - DEBUG - VN b19e0c1d-f727-4c4d-9fa3-190c6c10b68b still in use: Unable to complete operation on network b19e0c1d-f727-4c4d-9fa3-190c6c10b68b. There are one or more ports still in use on the network.
Neutron server returns request_ids: ['req-90d77d84-b179-4e40-b6b6-1ed5772440d5']
2025-08-06 09:53:32,252 - WARNING - Deleting VN ctest-dsnat_vn-43004073 failed..Will retry
2025-08-06 09:53:34,467 - DEBUG - Response for deleting network ()
2025-08-06 09:53:35,734 - ERROR - AssertionError
Python 3.6.8: /usr/bin/python3
Wed Aug 6 09:53:31 2025
A problem occurred in a Python script. Here is the sequence of
function calls leading up to the error, in the order they occurred.
/contrail-test/tcutils/wrappers.py in wrapper(self=, *args=(), **kwargs={})
78 log.info('Initial checks done. Running the testcase now')
79 log.info('')
80 result = function(self, *args, **kwargs)
81 if self.inputs.upgrade:
82 pid = os.getpid()
result = None
function =
self =
args = ()
kwargs = {}
/contrail-test/serial_scripts/dsnat/test_dsnat.py in test_dsnat_udp_basic(self=)
59 self.iperf = None
60
61 assert self.verify_flow_with_port(vm1_fixture, vm2_fixture, port_range, **traffic)
62
63
self =
self.verify_flow_with_port = .deco_retry.....test_dsnat_udp_basic[sanity] id=0x7f8cd79c5780>>
vm1_fixture =
vm2_fixture =
port_range = [65000, 65001, 65002, 65003, 65004, 65005, 65006, 65007, 65008, 65009]
traffic = {'port': 5201, 'udp': True}
AssertionError:
__cause__ = None
__class__ =
__context__ = None
__delattr__ =
__dict__ = {}
__dir__ =
__doc__ = 'Assertion failed.'
__eq__ =
__format__ =
__ge__ =
__getattribute__ =
__gt__ =
__hash__ =
__init__ =
__init_subclass__ =
__le__ =
__lt__ =
__ne__ =
__new__ =
__reduce__ =
__reduce_ex__ =
__repr__ =
__setattr__ =
__setstate__ =
__sizeof__ =
__str__ =
__subclasshook__ =
__suppress_context__ = False
__traceback__ =
args = ()
with_traceback =
The above is a description of an error in a Python program. Here is
the original traceback:
Traceback (most recent call last):
File "/contrail-test/tcutils/wrappers.py", line 80, in wrapper
result = function(self, *args, **kwargs)
File "/contrail-test/serial_scripts/dsnat/test_dsnat.py", line 61, in test_dsnat_udp_basic
assert self.verify_flow_with_port(vm1_fixture, vm2_fixture, port_range, **traffic)
AssertionError
2025-08-06 09:53:35,734 - DEBUG - Skipping xmpp flap check
2025-08-06 09:53:35,734 - INFO -
2025-08-06 09:53:35,734 - INFO - END TEST : test_dsnat_udp_basic : FAILED[0:02:33]
2025-08-06 09:53:35,734 - INFO - --------------------------------------------------------------------------------
2025-08-06 09:53:36,627 - INFO - Deleted project: ctest-TestDSNAT-36030765, ID : 10101526-7735-428a-ad98-9d25fd799dc6