]
2025-07-22 15:15:55,658 - DEBUG - Image by name ubuntu not found
2025-07-22 15:15:55,658 - DEBUG - Installing image ubuntu
2025-07-22 15:15:55,658 - DEBUG - Image info {'name': 'ubuntu.vmdk.gz', 'webserver': '', 'location': '/images/converts/', 'username': 'ubuntu', 'password': 'ubuntu', 'type': 'os', 'flavor': 'contrail_flavor_tiny', 'params': '--container-format bare --disk-format vmdk --property vmware_disktype="sparse" --property vmware_adaptertype="ide" --property hw_scsi_model=virtio-scsi --property hw_disk_bus_model=virtio-scsi --property hw_disk_bus=virtio', 'name_docker': 'phusion-baseimage-enablesshd'}
2025-07-22 15:15:55,659 - DEBUG - Image build path http://nexus.opensdn.io/repository///images/converts//ubuntu.vmdk.gz
2025-07-22 15:15:55,659 - DEBUG - Download image from web http://nexus.opensdn.io/repository///images/converts//ubuntu.vmdk.gz
2025-07-22 15:15:55,669 - DEBUG - Image download (local=True) (proxy=None): Execute cmd: wget -nv http://nexus.opensdn.io/repository///images/converts//ubuntu.vmdk.gz -O /contrail-test/images/ubuntu.vmdk.gz
2025-07-22 15:15:55,698 - DEBUG - Image has been downloaded to /contrail-test/images/ubuntu.vmdk.gz
2025-07-22 15:15:55,699 - DEBUG - Unzip image
2025-07-22 15:15:55,699 - DEBUG - Image download (local=True) (proxy=None): Execute cmd: gunzip -f /contrail-test/images/ubuntu.vmdk.gz
2025-07-22 15:15:55,710 - DEBUG - Try to create image in user context
2025-07-22 15:15:55,786 - INFO - Deleting VN ctest-dsnat_vn-59716798
2025-07-22 15:15:56,006 - DEBUG - Response for deleting network ()
2025-07-22 15:15:57,269 - ERROR - Traceback (most recent call last):
File "/contrail-test/tcutils/wrappers.py", line 80, in wrapper
result = function(self, *args, **kwargs)
File "/contrail-test/scripts/dsnat/test_dsnat.py", line 30, in test_dsnat_basic
image_name='ubuntu')
File "/contrail-test/common/base.py", line 281, in create_vm
**kwargs)
File "/contrail-test/common/base.py", line 254, in create_only_vm
vm_obj.setUp()
File "/contrail-test/fixtures/vm_test.py", line 188, in setUp
self.create()
File "/contrail-test/fixtures/vm_test.py", line 240, in create
fixed_ips=self.fixed_ips)
File "/contrail-test/fixtures/openstack.py", line 118, in create_vm
return self.nova_h.create_vm(vm_name=vm_name, image_name=image_name, vn_ids=vn_ids, **kwargs)
File "/contrail-test/fixtures/nova_test.py", line 577, in create_vm
image = self.get_image(image_name=image_name)
File "/contrail-test/fixtures/nova_test.py", line 198, in get_image
self._install_image(image_name=image_name)
File "/contrail-test/fixtures/nova_test.py", line 338, in _install_image
return self.copy_and_glance(build_path, image_name, params)
File "/contrail-test/fixtures/nova_test.py", line 407, in copy_and_glance
image_id = self.glance_h.create_image(generic_image_name, image_path_real, **params)
File "/contrail-test/fixtures/glance_test.py", line 50, in create_image
self.upload_image(obj['id'], filename)
File "/contrail-test/fixtures/glance_test.py", line 54, in upload_image
self.obj.images.upload(uuid, open(filename, 'rb'))
FileNotFoundError: [Errno 2] No such file or directory: '/contrail-test/images/ubuntu.vmdk'
2025-07-22 15:15:57,284 - DEBUG - No XMPP flaps were noticed during the test
2025-07-22 15:15:57,284 - INFO -
2025-07-22 15:15:57,284 - INFO - END TEST : test_dsnat_basic : FAILED[0:00:05]
2025-07-22 15:15:57,284 - INFO - --------------------------------------------------------------------------------
2025-07-22 15:15:57,288 - DEBUG - Hosts: {'nova': ['an-jenkins-deploy-platform-ansible-os-3693-2', 'an-jenkins-deploy-platform-ansible-os-3693-1']}
2025-07-22 15:15:57,288 - INFO - ================================================================================
2025-07-22 15:15:57,288 - INFO - STARTING TEST : test_dsnat_bug_1749695
2025-07-22 15:15:57,288 - INFO - TEST DESCRIPTION :
Testcase to verify the bug 1749695
create test VN , associate a policy to allow all traffic between VN and ip fabric
associate the policy to the test VN and fabric VN
set the test VN fabric mode as l3
verify the ping succeeds for intra VN and to the fabric IP
2025-07-22 15:15:58,564 - DEBUG - Nothing to compare xmpp stats {'10.0.0.19': {'10.20.0.14': '0', '10.20.0.17': '0'}, '10.0.0.27': {'10.20.0.14': '0', '10.20.0.254': '0'}} with
2025-07-22 15:15:58,564 - INFO - Initial checks done. Running the testcase now
2025-07-22 15:15:58,564 - INFO -
2025-07-22 15:15:58,564 - INFO - Create VN, enable FABRIC SNAT and verify its routing instance
2025-07-22 15:15:58,928 - DEBUG - Response for create_network : {'network': {'id': 'cd17e757-dbbd-4e96-83a8-905a19b8bb35', 'name': 'ctest-dsnat_vn-49253853', 'tenant_id': '5a73d6f7d70f41beb7cf4b29638c4962', 'project_id': '5a73d6f7d70f41beb7cf4b29638c4962', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': False, 'mtu': 0, 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestDSNAT-56449480', 'ctest-dsnat_vn-49253853'], 'port_security_enabled': True, 'description': ''}}
2025-07-22 15:15:59,219 - DEBUG - Response for create_subnet : {'subnet': {'id': '24bf4d76-7078-4a5c-9a01-64590fb712b5', 'name': '', 'tenant_id': '5a73d6f7d70f41beb7cf4b29638c4962', 'network_id': 'cd17e757-dbbd-4e96-83a8-905a19b8bb35', 'ip_version': 4, 'cidr': '54.34.36.0/26', 'allocation_pools': [{'start': '54.34.36.2', 'end': '54.34.36.62'}], 'gateway_ip': '54.34.36.1', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '54.34.36.2', 'tags': [], 'project_id': '5a73d6f7d70f41beb7cf4b29638c4962'}}
2025-07-22 15:15:59,243 - INFO - Created VN ctest-dsnat_vn-49253853
2025-07-22 15:15:59,258 - DEBUG - VN ctest-dsnat_vn-49253853 UUID is cd17e757-dbbd-4e96-83a8-905a19b8bb35
2025-07-22 15:15:59,490 - DEBUG - Requesting: http://10.0.0.254:8082/virtual-network/cd17e757-dbbd-4e96-83a8-905a19b8bb35
2025-07-22 15:15:59,521 - DEBUG - Requesting: http://10.0.0.254:8082/routing-instance/b5f137aa-ed95-4314-9a24-31a46733fc26
2025-07-22 15:15:59,749 - DEBUG - Image by name ubuntu-traffic not found
2025-07-22 15:15:59,749 - DEBUG - Installing image ubuntu-traffic
2025-07-22 15:15:59,749 - DEBUG - Image info {'name': 'ubuntu-traffic.vmdk.gz', 'webserver': '', 'location': '/images/converts/', 'username': 'ubuntu', 'password': 'ubuntu', 'type': 'os', 'flavor': 'contrail_flavor_small', 'params': '--container-format bare --disk-format vmdk --property vmware_disktype="sparse" --property vmware_adaptertype="ide" --property hw_scsi_model=virtio-scsi --property hw_disk_bus_model=virtio-scsi --property hw_disk_bus=virtio', 'name_docker': 'ubuntu-traffic-docker', 'vmdk': 'ubuntu-traffic-disk1.vmdk', 'shrinked_vmdk': "'no'"}
2025-07-22 15:15:59,749 - DEBUG - Image build path http://nexus.opensdn.io/repository///images/converts//ubuntu-traffic.vmdk.gz
2025-07-22 15:15:59,749 - DEBUG - Download image from web http://nexus.opensdn.io/repository///images/converts//ubuntu-traffic.vmdk.gz
2025-07-22 15:15:59,759 - DEBUG - Image download (local=True) (proxy=None): Execute cmd: wget -nv http://nexus.opensdn.io/repository///images/converts//ubuntu-traffic.vmdk.gz -O /contrail-test/images/ubuntu-traffic.vmdk.gz
2025-07-22 15:16:04,949 - DEBUG - Image has been downloaded to /contrail-test/images/ubuntu-traffic.vmdk.gz
2025-07-22 15:16:04,950 - DEBUG - Unzip image
2025-07-22 15:16:04,950 - DEBUG - Image download (local=True) (proxy=None): Execute cmd: gunzip -f /contrail-test/images/ubuntu-traffic.vmdk.gz
2025-07-22 15:16:22,405 - DEBUG - Try to create image in user context
2025-07-22 15:16:32,912 - DEBUG - Image has been created in user context
2025-07-22 15:16:32,913 - DEBUG - Image download (local=True) (proxy=None): Execute cmd: rm -f /contrail-test/images/ubuntu-traffic.vmdk
2025-07-22 15:16:33,138 - DEBUG - Downloaded image has been removed
2025-07-22 15:16:33,152 - DEBUG - Uploaded image status = active
2025-07-22 15:16:34,348 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-3693-1), Zone: (nova:an-jenkins-deploy-platform-ansible-os-3693-1)
2025-07-22 15:16:36,033 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-3693-2), Zone: (nova:an-jenkins-deploy-platform-ansible-os-3693-2)
2025-07-22 15:16:36,033 - INFO - Waiting for VM ctest-TestDSNAT-56449480-21080369 to be up..
2025-07-22 15:16:36,184 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2025-07-22 15:16:41,346 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2025-07-22 15:16:46,503 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2025-07-22 15:16:51,660 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2025-07-22 15:16:56,804 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2025-07-22 15:17:01,957 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2025-07-22 15:17:07,130 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2025-07-22 15:17:12,272 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2025-07-22 15:17:17,359 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2025-07-22 15:17:22,459 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2025-07-22 15:17:27,571 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2025-07-22 15:17:32,654 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2025-07-22 15:17:37,748 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2025-07-22 15:17:42,840 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2025-07-22 15:17:47,936 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2025-07-22 15:17:53,025 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2025-07-22 15:17:58,131 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2025-07-22 15:18:03,217 - DEBUG - VM is in ACTIVE state now
2025-07-22 15:18:03,217 - INFO - VM name : ctest-TestDSNAT-56449480-21080369
2025-07-22 15:18:03,326 - DEBUG - VM ctest-TestDSNAT-56449480-21080369 ID is 86004ff6-2871-4f9d-9692-0ff226f9f7fa
2025-07-22 15:18:03,355 - DEBUG - VM ctest-TestDSNAT-56449480-21080369 launched on Node an-jenkins-deploy-platform-ansible-os-3693-1
2025-07-22 15:18:03,447 - DEBUG - Requesting: http://10.0.0.23:8082/virtual-machine/86004ff6-2871-4f9d-9692-0ff226f9f7fa
2025-07-22 15:18:03,745 - DEBUG - Requesting: http://10.0.0.23:8082/virtual-machine/86004ff6-2871-4f9d-9692-0ff226f9f7fa
2025-07-22 15:18:03,783 - DEBUG - Requesting: http://10.0.0.23:8082/virtual-machine-interface/59bb1187-6ea9-491a-aecf-5d317994aa1a
2025-07-22 15:18:07,006 - 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-07-22 15:18:07,006 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestDSNAT-56449480-21080369 failed!
2025-07-22 15:18:07,025 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-56449480:ctest-dsnat_vn-49253853 is 54.34.36.1 and allocation pool is NOT set
2025-07-22 15:18:11,110 - 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 1018ms')
2025-07-22 15:18:11,110 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestDSNAT-56449480-21080369 failed!
2025-07-22 15:18:11,131 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-56449480:ctest-dsnat_vn-49253853 is 54.34.36.1 and allocation pool is NOT set
2025-07-22 15:18:15,206 - 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-07-22 15:18:15,207 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestDSNAT-56449480-21080369 failed!
2025-07-22 15:18:15,225 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-56449480:ctest-dsnat_vn-49253853 is 54.34.36.1 and allocation pool is NOT set
2025-07-22 15:18:19,304 - 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-07-22 15:18:19,304 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestDSNAT-56449480-21080369 failed!
2025-07-22 15:18:19,324 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-56449480:ctest-dsnat_vn-49253853 is 54.34.36.1 and allocation pool is NOT set
2025-07-22 15:18:23,398 - 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-07-22 15:18:23,398 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestDSNAT-56449480-21080369 failed!
2025-07-22 15:18:23,425 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-56449480:ctest-dsnat_vn-49253853 is 54.34.36.1 and allocation pool is NOT set
2025-07-22 15:18:27,527 - 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 1037ms')
2025-07-22 15:18:27,527 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestDSNAT-56449480-21080369 failed!
2025-07-22 15:18:27,549 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-56449480:ctest-dsnat_vn-49253853 is 54.34.36.1 and allocation pool is NOT set
2025-07-22 15:18:31,622 - 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-07-22 15:18:31,622 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestDSNAT-56449480-21080369 failed!
2025-07-22 15:18:31,643 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-56449480:ctest-dsnat_vn-49253853 is 54.34.36.1 and allocation pool is NOT set
2025-07-22 15:18:35,718 - 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-07-22 15:18:35,718 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestDSNAT-56449480-21080369 failed!
2025-07-22 15:18:35,736 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-56449480:ctest-dsnat_vn-49253853 is 54.34.36.1 and allocation pool is NOT set
2025-07-22 15:18:39,807 - 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 1012ms')
2025-07-22 15:18:39,807 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestDSNAT-56449480-21080369 failed!
2025-07-22 15:18:39,827 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-56449480:ctest-dsnat_vn-49253853 is 54.34.36.1 and allocation pool is NOT set
2025-07-22 15:18:41,892 - 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.10 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=6.75 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 = 6.095/6.420/6.745/0.325 ms')
2025-07-22 15:18:41,893 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-TestDSNAT-56449480-21080369 passed
2025-07-22 15:18:42,019 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-07-22 15:18:42,019 - DEBUG - Waiting to SSH to VM ctest-TestDSNAT-56449480-21080369, IP 54.34.36.3, Port 22
2025-07-22 15:18:42,088 - 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-07-22 15:18:42,204 - DEBUG - VM ctest-TestDSNAT-56449480-21080369 is NOT ready for SSH connections, VM status: ACTIVE
2025-07-22 15:18:47,205 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-07-22 15:18:47,205 - DEBUG - Waiting to SSH to VM ctest-TestDSNAT-56449480-21080369, IP 54.34.36.3, Port 22
2025-07-22 15:18:47,271 - 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-07-22 15:18:47,361 - DEBUG - VM ctest-TestDSNAT-56449480-21080369 is NOT ready for SSH connections, VM status: ACTIVE
2025-07-22 15:18:52,363 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-07-22 15:18:52,363 - DEBUG - Waiting to SSH to VM ctest-TestDSNAT-56449480-21080369, IP 54.34.36.3, Port 22
2025-07-22 15:18:52,431 - 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-07-22 15:18:52,521 - DEBUG - VM ctest-TestDSNAT-56449480-21080369 is NOT ready for SSH connections, VM status: ACTIVE
2025-07-22 15:18:57,522 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-07-22 15:18:57,523 - DEBUG - Waiting to SSH to VM ctest-TestDSNAT-56449480-21080369, IP 54.34.36.3, Port 22
2025-07-22 15:18:57,590 - 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-07-22 15:18:57,686 - DEBUG - VM ctest-TestDSNAT-56449480-21080369 is NOT ready for SSH connections, VM status: ACTIVE
2025-07-22 15:19:02,687 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-07-22 15:19:02,687 - DEBUG - Waiting to SSH to VM ctest-TestDSNAT-56449480-21080369, IP 54.34.36.3, Port 22
2025-07-22 15:19:02,855 - DEBUG - VM ctest-TestDSNAT-56449480-21080369 is ready for SSH connections
2025-07-22 15:19:02,855 - INFO - Waiting for VM ctest-TestDSNAT-56449480-51679815 to be up..
2025-07-22 15:19:02,944 - DEBUG - VM is in ACTIVE state now
2025-07-22 15:19:02,944 - INFO - VM name : ctest-TestDSNAT-56449480-51679815
2025-07-22 15:19:03,039 - DEBUG - VM ctest-TestDSNAT-56449480-51679815 ID is 81e63db2-9fb5-430c-81aa-de87adb2f924
2025-07-22 15:19:03,039 - DEBUG - VM ctest-TestDSNAT-56449480-51679815 launched on Node an-jenkins-deploy-platform-ansible-os-3693-2
2025-07-22 15:19:03,126 - DEBUG - Requesting: http://10.0.0.23:8082/virtual-machine/81e63db2-9fb5-430c-81aa-de87adb2f924
2025-07-22 15:19:03,138 - DEBUG - Requesting: http://10.0.0.23:8082/virtual-machine-interface/c2088f9e-ce90-4b80-bc64-472ed2d912aa
2025-07-22 15:19:04,359 - 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.64 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.261/3.451/5.642/2.190 ms')
2025-07-22 15:19:04,359 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-TestDSNAT-56449480-51679815 passed
2025-07-22 15:19:04,475 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-07-22 15:19:04,475 - DEBUG - Waiting to SSH to VM ctest-TestDSNAT-56449480-51679815, IP 54.34.36.4, Port 22
2025-07-22 15:19:04,637 - DEBUG - VM ctest-TestDSNAT-56449480-51679815 is ready for SSH connections
2025-07-22 15:19:04,793 - DEBUG - Fetched VN: default-domain:default-project:ip-fabric(7bd0b25e-be2b-42b9-83bc-fc1d418ae60e) with subnets None
2025-07-22 15:19:04,840 - DEBUG - Policy np_rules : [rule_sequence = None, rule_uuid = None, direction = <>, protocol = any, src_addresses = [subnet = None, virtual_network = default-domain:ctest-TestDSNAT-56449480:ctest-dsnat_vn-49253853, 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-07-22 15:19:05,241 - INFO - Attaching policy ctest-test-dsnat-20728421 to vn ctest-dsnat_vn-49253853
2025-07-22 15:19:05,820 - INFO - Attaching policy ctest-test-dsnat-20728421 to vn ip-fabric
2025-07-22 15:19:06,116 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 3 -W 1 10.20.0.17, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.19, gateway password: c0ntrail123
2025-07-22 15:19:06,117 - DEBUG - ping -s 56 -c 3 -W 1 10.20.0.17
2025-07-22 15:19:29,108 - DEBUG - PING 10.20.0.17 (10.20.0.17) 56(84) bytes of data.
--- 10.20.0.17 ping statistics ---
3 packets transmitted, 0 received, 100% packet loss, time 2017ms
2025-07-22 15:19:29,108 - WARNING - Ping to IP 10.20.0.17 from VM ctest-TestDSNAT-56449480-21080369 failed
2025-07-22 15:19:30,108 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 3 -W 1 10.20.0.17, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.19, gateway password: c0ntrail123
2025-07-22 15:19:30,109 - DEBUG - ping -s 56 -c 3 -W 1 10.20.0.17
2025-07-22 15:19:32,629 - DEBUG - PING 10.20.0.17 (10.20.0.17) 56(84) bytes of data.
64 bytes from 10.20.0.17: icmp_req=1 ttl=62 time=4.35 ms
64 bytes from 10.20.0.17: icmp_req=2 ttl=62 time=0.578 ms
64 bytes from 10.20.0.17: icmp_req=3 ttl=62 time=0.784 ms
--- 10.20.0.17 ping statistics ---
3 packets transmitted, 3 received, 0% packet loss, time 2004ms
rtt min/avg/max/mdev = 0.578/1.904/4.351/1.732 ms
2025-07-22 15:19:32,630 - INFO - Ping to IP 10.20.0.17 from VM ctest-TestDSNAT-56449480-21080369 passed
2025-07-22 15:19:32,748 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 3 -W 1 10.20.0.17, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.19, gateway password: c0ntrail123
2025-07-22 15:19:32,748 - DEBUG - ping -s 56 -c 3 -W 1 10.20.0.17
2025-07-22 15:19:36,275 - DEBUG - PING 10.20.0.17 (10.20.0.17) 56(84) bytes of data.
--- 10.20.0.17 ping statistics ---
3 packets transmitted, 0 received, 100% packet loss, time 2015ms
2025-07-22 15:19:36,275 - WARNING - Ping to IP 10.20.0.17 from VM ctest-TestDSNAT-56449480-21080369 failed
2025-07-22 15:19:37,276 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 3 -W 1 10.20.0.17, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.19, gateway password: c0ntrail123
2025-07-22 15:19:37,276 - DEBUG - ping -s 56 -c 3 -W 1 10.20.0.17
2025-07-22 15:19:40,809 - DEBUG - PING 10.20.0.17 (10.20.0.17) 56(84) bytes of data.
--- 10.20.0.17 ping statistics ---
3 packets transmitted, 0 received, 100% packet loss, time 2016ms
2025-07-22 15:19:40,809 - WARNING - Ping to IP 10.20.0.17 from VM ctest-TestDSNAT-56449480-21080369 failed
2025-07-22 15:19:41,810 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 3 -W 1 10.20.0.17, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.19, gateway password: c0ntrail123
2025-07-22 15:19:41,810 - DEBUG - ping -s 56 -c 3 -W 1 10.20.0.17
2025-07-22 15:19:44,322 - DEBUG - PING 10.20.0.17 (10.20.0.17) 56(84) bytes of data.
64 bytes from 10.20.0.17: icmp_req=1 ttl=62 time=1.81 ms
64 bytes from 10.20.0.17: icmp_req=2 ttl=62 time=0.595 ms
64 bytes from 10.20.0.17: icmp_req=3 ttl=62 time=0.565 ms
--- 10.20.0.17 ping statistics ---
3 packets transmitted, 3 received, 0% packet loss, time 2004ms
rtt min/avg/max/mdev = 0.565/0.992/1.818/0.584 ms
2025-07-22 15:19:44,322 - INFO - Ping to IP 10.20.0.17 from VM ctest-TestDSNAT-56449480-21080369 passed
2025-07-22 15:19:44,322 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-07-22 15:19:44,322 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 3 -W 1 54.34.36.4, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.19, gateway password: c0ntrail123
2025-07-22 15:19:44,322 - DEBUG - ping -s 56 -c 3 -W 1 54.34.36.4
2025-07-22 15:19:46,870 - DEBUG - PING 54.34.36.4 (54.34.36.4) 56(84) bytes of data.
64 bytes from 54.34.36.4: icmp_req=1 ttl=63 time=13.0 ms
64 bytes from 54.34.36.4: icmp_req=2 ttl=63 time=1.29 ms
64 bytes from 54.34.36.4: icmp_req=3 ttl=63 time=1.26 ms
--- 54.34.36.4 ping statistics ---
3 packets transmitted, 3 received, 0% packet loss, time 2003ms
rtt min/avg/max/mdev = 1.269/5.221/13.099/5.570 ms
2025-07-22 15:19:46,870 - INFO - Ping to IP 54.34.36.4 from VM ctest-TestDSNAT-56449480-21080369 passed
2025-07-22 15:19:46,870 - INFO - Dettaching policy ctest-test-dsnat-20728421 from vn ip-fabric
2025-07-22 15:19:47,117 - INFO - Dettaching policy ctest-test-dsnat-20728421 from vn ctest-dsnat_vn-49253853
2025-07-22 15:19:47,389 - INFO - Deleted policy ctest-test-dsnat-20728421
2025-07-22 15:19:47,389 - INFO - Deleting VM ctest-TestDSNAT-56449480-51679815
2025-07-22 15:19:47,458 - INFO - Deleting VM ctest-TestDSNAT-56449480-21080369
2025-07-22 15:19:47,540 - INFO - Deleting VN ctest-dsnat_vn-49253853
2025-07-22 15:19:47,590 - DEBUG - VN cd17e757-dbbd-4e96-83a8-905a19b8bb35 still in use: Unable to complete operation on network cd17e757-dbbd-4e96-83a8-905a19b8bb35. There are one or more ports still in use on the network.
Neutron server returns request_ids: ['req-051b4bfb-24cb-4abd-a3be-ff12ffc18d4b']
2025-07-22 15:19:47,590 - WARNING - Deleting VN ctest-dsnat_vn-49253853 failed..Will retry
2025-07-22 15:19:49,759 - DEBUG - Response for deleting network ()
2025-07-22 15:19:51,061 - DEBUG - No XMPP flaps were noticed during the test
2025-07-22 15:19:51,062 - INFO - END TEST : test_dsnat_bug_1749695 : PASSED[0:03:54]
2025-07-22 15:19:51,062 - INFO - --------------------------------------------------------------------------------
2025-07-22 15:19:51,838 - INFO - Deleted project: ctest-TestDSNAT-56449480, ID : 5a73d6f7-d70f-41be-b7cf-4b29638c4962
2025-07-22 17:51:41,126 - INFO - Domain Default found not creating
2025-07-22 17:51:41,292 - INFO - Project ctest-TestDSNAT-87744787 not found, creating it
2025-07-22 17:51:41,883 - INFO - Created Project:ctest-TestDSNAT-87744787, ID : 7996ea1d-fe74-4a2c-a231-926075380c2a
2025-07-22 17:51:43,434 - DEBUG - Services list from nova: [, , , ]
2025-07-22 17:51:43,434 - DEBUG - Hosts: {'nova': ['an-jenkins-deploy-platform-ansible-os-3693-2', 'an-jenkins-deploy-platform-ansible-os-3693-1']}
2025-07-22 17:51:43,434 - INFO - ================================================================================
2025-07-22 17:51:43,434 - INFO - STARTING TEST : test_dsnat_tcp_basic
2025-07-22 17:51:43,435 - 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-07-22 17:51:44,681 - DEBUG - Skipping xmpp flap check
2025-07-22 17:51:44,681 - INFO - Initial checks done. Running the testcase now
2025-07-22 17:51:44,681 - INFO -
2025-07-22 17:51:45,148 - INFO - Create VN, enable FABRIC SNAT and verify its routing instance
2025-07-22 17:51:45,540 - DEBUG - Response for create_network : {'network': {'id': '4df11a57-ed11-4255-be76-e8f7e98f2da9', 'name': 'ctest-dsnat_vn-17347303', 'tenant_id': '7996ea1dfe744a2ca231926075380c2a', 'project_id': '7996ea1dfe744a2ca231926075380c2a', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': False, 'mtu': 0, 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestDSNAT-87744787', 'ctest-dsnat_vn-17347303'], 'port_security_enabled': True, 'description': ''}}
2025-07-22 17:51:45,788 - DEBUG - Response for create_subnet : {'subnet': {'id': '4e43aaf1-099f-4c3b-b674-bd2ad3668e61', 'name': '', 'tenant_id': '7996ea1dfe744a2ca231926075380c2a', 'network_id': '4df11a57-ed11-4255-be76-e8f7e98f2da9', 'ip_version': 4, 'cidr': '166.243.124.128/26', 'allocation_pools': [{'start': '166.243.124.130', 'end': '166.243.124.190'}], 'gateway_ip': '166.243.124.129', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '166.243.124.130', 'tags': [], 'project_id': '7996ea1dfe744a2ca231926075380c2a'}}
2025-07-22 17:51:45,818 - INFO - Created VN ctest-dsnat_vn-17347303
2025-07-22 17:51:45,836 - DEBUG - VN ctest-dsnat_vn-17347303 UUID is 4df11a57-ed11-4255-be76-e8f7e98f2da9
2025-07-22 17:51:46,041 - DEBUG - Requesting: http://10.0.0.254:8082/virtual-network/4df11a57-ed11-4255-be76-e8f7e98f2da9
2025-07-22 17:51:46,353 - DEBUG - Requesting: http://10.0.0.254:8082/virtual-network/4df11a57-ed11-4255-be76-e8f7e98f2da9
2025-07-22 17:51:46,411 - DEBUG - Requesting: http://10.0.0.254:8082/routing-instance/8249da89-87c7-4453-b021-d43bbf7e3189
2025-07-22 17:51:47,714 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-3693-1), Zone: (nova:an-jenkins-deploy-platform-ansible-os-3693-1)
2025-07-22 17:51:49,106 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-3693-2), Zone: (nova:an-jenkins-deploy-platform-ansible-os-3693-2)
2025-07-22 17:51:49,106 - INFO - Waiting for VM ctest-dsnat-vm1-88706784 to be up..
2025-07-22 17:51:49,212 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2025-07-22 17:51:54,303 - DEBUG - VM is in ACTIVE state now
2025-07-22 17:51:54,303 - INFO - VM name : ctest-dsnat-vm1-88706784
2025-07-22 17:51:54,384 - DEBUG - VM ctest-dsnat-vm1-88706784 ID is 4ae53a8a-1dee-47c0-b5a5-88a8174abeab
2025-07-22 17:51:54,408 - DEBUG - VM ctest-dsnat-vm1-88706784 launched on Node an-jenkins-deploy-platform-ansible-os-3693-1
2025-07-22 17:51:54,494 - DEBUG - Requesting: http://10.0.0.23:8082/virtual-machine/4ae53a8a-1dee-47c0-b5a5-88a8174abeab
2025-07-22 17:51:54,794 - DEBUG - Requesting: http://10.0.0.23:8082/virtual-machine/4ae53a8a-1dee-47c0-b5a5-88a8174abeab
2025-07-22 17:51:54,830 - DEBUG - Requesting: http://10.0.0.23:8082/virtual-machine-interface/0a543a4e-dad5-46ae-8a2d-a8f9f205ea56
2025-07-22 17:51:58,015 - 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 1021ms')
2025-07-22 17:51:58,015 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-88706784 failed!
2025-07-22 17:51:58,112 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-87744787:ctest-dsnat_vn-17347303 is 166.243.124.129 and allocation pool is NOT set
2025-07-22 17:52:02,177 - 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 1006ms')
2025-07-22 17:52:02,177 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-88706784 failed!
2025-07-22 17:52:02,195 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-87744787:ctest-dsnat_vn-17347303 is 166.243.124.129 and allocation pool is NOT set
2025-07-22 17:52:06,274 - 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 1018ms')
2025-07-22 17:52:06,275 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-88706784 failed!
2025-07-22 17:52:06,295 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-87744787:ctest-dsnat_vn-17347303 is 166.243.124.129 and allocation pool is NOT set
2025-07-22 17:52:10,378 - 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-07-22 17:52:10,378 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-88706784 failed!
2025-07-22 17:52:10,396 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-87744787:ctest-dsnat_vn-17347303 is 166.243.124.129 and allocation pool is NOT set
2025-07-22 17:52:14,466 - 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-07-22 17:52:14,466 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-88706784 failed!
2025-07-22 17:52:14,484 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-87744787:ctest-dsnat_vn-17347303 is 166.243.124.129 and allocation pool is NOT set
2025-07-22 17:52:18,569 - 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 1023ms')
2025-07-22 17:52:18,569 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-88706784 failed!
2025-07-22 17:52:18,586 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-87744787:ctest-dsnat_vn-17347303 is 166.243.124.129 and allocation pool is NOT set
2025-07-22 17:52:22,656 - 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-07-22 17:52:22,657 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-88706784 failed!
2025-07-22 17:52:22,675 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-87744787:ctest-dsnat_vn-17347303 is 166.243.124.129 and allocation pool is NOT set
2025-07-22 17:52:26,751 - 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 1018ms')
2025-07-22 17:52:26,751 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-88706784 failed!
2025-07-22 17:52:26,769 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-87744787:ctest-dsnat_vn-17347303 is 166.243.124.129 and allocation pool is NOT set
2025-07-22 17:52:30,847 - 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=2 ttl=63 time=7.37 ms\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 1 received, 50% packet loss, time 1023ms\r\nrtt min/avg/max/mdev = 7.371/7.371/7.371/0.000 ms')
2025-07-22 17:52:30,847 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-88706784 passed
2025-07-22 17:52:30,923 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-07-22 17:52:30,925 - DEBUG - Waiting to SSH to VM ctest-dsnat-vm1-88706784, IP 166.243.124.131, Port 22
2025-07-22 17:52:30,990 - 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-07-22 17:52:31,086 - DEBUG - VM ctest-dsnat-vm1-88706784 is NOT ready for SSH connections, VM status: ACTIVE
2025-07-22 17:52:36,087 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-07-22 17:52:36,087 - DEBUG - Waiting to SSH to VM ctest-dsnat-vm1-88706784, IP 166.243.124.131, Port 22
2025-07-22 17:52:36,165 - 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-07-22 17:52:36,254 - DEBUG - VM ctest-dsnat-vm1-88706784 is NOT ready for SSH connections, VM status: ACTIVE
2025-07-22 17:52:41,255 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-07-22 17:52:41,255 - DEBUG - Waiting to SSH to VM ctest-dsnat-vm1-88706784, IP 166.243.124.131, Port 22
2025-07-22 17:52:41,324 - 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-07-22 17:52:41,409 - DEBUG - VM ctest-dsnat-vm1-88706784 is NOT ready for SSH connections, VM status: ACTIVE
2025-07-22 17:52:46,410 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-07-22 17:52:46,410 - DEBUG - Waiting to SSH to VM ctest-dsnat-vm1-88706784, IP 166.243.124.131, Port 22
2025-07-22 17:52:46,479 - 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-07-22 17:52:46,563 - DEBUG - VM ctest-dsnat-vm1-88706784 is NOT ready for SSH connections, VM status: ACTIVE
2025-07-22 17:52:51,564 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-07-22 17:52:51,564 - DEBUG - Waiting to SSH to VM ctest-dsnat-vm1-88706784, IP 166.243.124.131, Port 22
2025-07-22 17:52:51,731 - DEBUG - VM ctest-dsnat-vm1-88706784 is ready for SSH connections
2025-07-22 17:52:51,731 - INFO - Waiting for VM ctest-dsnat-vm2-82921712 to be up..
2025-07-22 17:52:51,811 - DEBUG - VM is in ACTIVE state now
2025-07-22 17:52:51,812 - INFO - VM name : ctest-dsnat-vm2-82921712
2025-07-22 17:52:51,888 - DEBUG - VM ctest-dsnat-vm2-82921712 ID is 3d684bc9-f6d5-40d0-82b5-201f547f0e4d
2025-07-22 17:52:51,888 - DEBUG - VM ctest-dsnat-vm2-82921712 launched on Node an-jenkins-deploy-platform-ansible-os-3693-2
2025-07-22 17:52:51,963 - DEBUG - Requesting: http://10.0.0.23:8082/virtual-machine/3d684bc9-f6d5-40d0-82b5-201f547f0e4d
2025-07-22 17:52:51,976 - DEBUG - Requesting: http://10.0.0.23:8082/virtual-machine-interface/8e440b92-d342-4e43-8f52-0d43c8ed1f9b
2025-07-22 17:52:53,158 - 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=8.64 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=2.76 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.762/5.702/8.642/2.940 ms')
2025-07-22 17:52:53,158 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm2-82921712 passed
2025-07-22 17:52:53,230 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-07-22 17:52:53,230 - DEBUG - Waiting to SSH to VM ctest-dsnat-vm2-82921712, IP 166.243.124.132, Port 22
2025-07-22 17:52:53,404 - DEBUG - VM ctest-dsnat-vm2-82921712 is ready for SSH connections
2025-07-22 17:52:53,508 - DEBUG - command output is cat: /tmp/iperf_server_ctest-random-01539455.pid: No such file or directory
kill: usage: kill [-s sigspec | -n signum | -sigspec] pid | jobspec ... or kill -l [sigspec]
2025-07-22 17:52:53,622 - DEBUG - command output is
2025-07-22 17:52:53,622 - INFO - Starting Iperf3 on ctest-dsnat-vm1-88706784, args: --port 6201 --length 1048576 --time 10
2025-07-22 17:52:53,622 - DEBUG - Iperf3 cmd : iperf3 -c 10.20.0.193 --port 6201 --length 1048576 --time 10 1>/tmp/iper3_ctest-random-01539455.log 2>/tmp/iper3_ctest-random-01539455.result
2025-07-22 17:52:53,622 - INFO - Excecuting cmds, ['iperf3 -s --port 6201 1>/tmp/iper3_ctest-random-01539455.log 2>/tmp/iper3_ctest-random-01539455.result'], on server 10.0.0.27
2025-07-22 17:52:53,729 - DEBUG - command output is ['']
2025-07-22 17:52:53,729 - DEBUG - Running remote_cmd, Cmd : iperf3 -c 10.20.0.193 --port 6201 --length 1048576 --time 10 1>/tmp/iper3_ctest-random-01539455.log 2>/tmp/iper3_ctest-random-01539455.result, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.19, gateway password: c0ntrail123
2025-07-22 17:52:53,729 - DEBUG - nohup iperf3 -c 10.20.0.193 --port 6201 --length 1048576 --time 10 1>/tmp/iper3_ctest-random-01539455.log 2>/tmp/iper3_ctest-random-01539455.result & echo $! > /tmp/iperf_client_ctest-random-01539455.pid
2025-07-22 17:53:21,485 - ERROR - Exception occured while running cmds ['iperf3 -c 10.20.0.193 --port 6201 --length 1048576 --time 10 1>/tmp/iper3_ctest-random-01539455.log 2>/tmp/iper3_ctest-random-01539455.result']
2025-07-22 17:53:21,485 - 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 2287, 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-07-22 17:53:25,031 - DEBUG - command output is /bin/bash: line 1: kill: (72155) - No such process
2025-07-22 17:53:25,132 - DEBUG - command output is
2025-07-22 17:53:25,133 - INFO - Deleting VM ctest-dsnat-vm2-82921712
2025-07-22 17:53:25,245 - INFO - Deleting VM ctest-dsnat-vm1-88706784
2025-07-22 17:53:25,346 - INFO - Deleting VN ctest-dsnat_vn-17347303
2025-07-22 17:53:25,405 - DEBUG - VN 4df11a57-ed11-4255-be76-e8f7e98f2da9 still in use: Unable to complete operation on network 4df11a57-ed11-4255-be76-e8f7e98f2da9. There are one or more ports still in use on the network.
Neutron server returns request_ids: ['req-f7573518-a1d7-4b9f-8609-b94bacebf042']
2025-07-22 17:53:25,406 - WARNING - Deleting VN ctest-dsnat_vn-17347303 failed..Will retry
2025-07-22 17:53:27,760 - DEBUG - Response for deleting network ()
2025-07-22 17:53:29,041 - ERROR - AttributeError
Python 3.6.8: /usr/bin/python3
Tue Jul 22 17:53:24 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=)
108 self.iperf = None
109
110 assert self.verify_flow_with_port(vm1_fixture, vm2_fixture, port_range, **traffic)
111
112 @preposttest_wrapper
self =
self.verify_flow_with_port = .deco_retry.....test_dsnat_tcp_basic[sanity] id=0x7f536e3df908>>
vm1_fixture =
vm2_fixture =
port_range = [65000, 65001, 65002, 65003, 65004, 65005, 65006, 65007, 65008, 65009]
traffic = {'port': 6201, 'udp': False}
/contrail-test/tcutils/util.py in f_retry(*args=(, , , [65000, 65001, 65002, 65003, 65004, 65005, 65006, 65007, 65008, 65009]), **kwargs={'port': 6201, 'udp': False})
82 mtries, mdelay = tries, delay # make mutable
83
84 result = f(*args, **kwargs) # first attempt
85 rv = result
86 final = False
result undefined
f =
args = (, , , [65000, 65001, 65002, 65003, 65004, 65005, 65006, 65007, 65008, 65009])
kwargs = {'port': 6201, 'udp': False}
/contrail-test/common/dsnat/base.py in verify_flow_with_port(self=, client_vm_fix=, dst_vm_fix=, port_range=[65000, 65001, 65002, 65003, 65004, 65005, 65006, 65007, 65008, 65009], **traffic={'port': 6201, 'udp': False})
200 else:
201 proto = '6'
202 nat_port_used = self.get_nat_port_used_for_flow(client_vm_fix, proto, traffic['port'])
203 self.iperf.stop_iperf_on_server()
204 self.logger.info("Nat port being used for the flow is %s" %nat_port_used)
nat_port_used undefined
self =
self.get_nat_port_used_for_flow = >
client_vm_fix =
proto = '6'
traffic = {'port': 6201, 'udp': False}
/contrail-test/common/dsnat/base.py in get_nat_port_used_for_flow(self=, vm_fix=, proto='6', port=6201, container='agent')
185 self.connections, vm_fix.vm_node_ip))
186 flow_entry = server_fixture.get_flow_entry(dest_ip=vm_fix.vm_node_data_ip,
187 proto=proto, source_port = port,all_flows=True)
188 nat_port = []
189 for flow in flow_entry:
proto = '6'
source_port undefined
port = 6201
all_flows undefined
/contrail-test/fixtures/compute_node_test.py in get_flow_entry(self=, flow_table=, index=None, source_ip=None, dest_ip='10.20.0.25', source_port=6201, dest_port=None, proto='6', vrf_id=None, refresh=True, show_evicted=True, all_flows=True)
561 all_flow_list = []
562 for flow_entry_item in flow_table.items:
563 if reqd_entries.viewitems() <= flow_entry_item.viewitems():
564 forward_flow = FlowEntry(flow_entry_item)
565 if flow_entry_item['rflow'] != '-1':
reqd_entries = {'dip': '10.20.0.25', 'proto': '6', 'sport': '6201'}
reqd_entries.viewitems undefined
flow_entry_item = {'action': 'DROP', 'bytes': '54', 'd_vrf_id': '0', 'dip': '155.169.32.66', 'dport': '54036', 'drop_reason': 'Unknown', 'flags': ' ACTIVE | EVICTED ', 'gen_id': '1', 'index': '32', 'insight': '0', ...}
flow_entry_item.viewitems undefined
AttributeError: 'dict' object has no attribute 'viewitems'
__cause__ = None
__class__ =
__context__ = None
__delattr__ =
__dict__ = {}
__dir__ =
__doc__ = 'Attribute not found.'
__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 = ("'dict' object has no attribute 'viewitems'",)
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 110, in test_dsnat_tcp_basic
assert self.verify_flow_with_port(vm1_fixture, vm2_fixture, port_range, **traffic)
File "/contrail-test/tcutils/util.py", line 84, in f_retry
result = f(*args, **kwargs) # first attempt
File "/contrail-test/common/dsnat/base.py", line 202, in verify_flow_with_port
nat_port_used = self.get_nat_port_used_for_flow(client_vm_fix, proto, traffic['port'])
File "/contrail-test/common/dsnat/base.py", line 187, in get_nat_port_used_for_flow
proto=proto, source_port = port,all_flows=True)
File "/contrail-test/fixtures/compute_node_test.py", line 563, in get_flow_entry
if reqd_entries.viewitems() <= flow_entry_item.viewitems():
AttributeError: 'dict' object has no attribute 'viewitems'
2025-07-22 17:53:29,042 - DEBUG - Skipping xmpp flap check
2025-07-22 17:53:29,042 - INFO -
2025-07-22 17:53:29,042 - INFO - END TEST : test_dsnat_tcp_basic : FAILED[0:01:46]
2025-07-22 17:53:29,043 - INFO - --------------------------------------------------------------------------------
2025-07-22 17:53:29,976 - INFO - Deleted project: ctest-TestDSNAT-87744787, ID : 7996ea1d-fe74-4a2c-a231-926075380c2a