]
2025-07-24 02:37:24,294 - DEBUG - Image by name ubuntu not found
2025-07-24 02:37:24,294 - DEBUG - Installing image ubuntu
2025-07-24 02:37:24,294 - 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', 'vctmpl': 'ubuntu.vmtx', 'vcname': 'ubuntu-disk1.vmdk'}
2025-07-24 02:37:24,294 - DEBUG - Image build path http://nexus.opensdn.io/repository///images/converts//ubuntu.vmdk.gz
2025-07-24 02:37:24,294 - DEBUG - Download image from web http://nexus.opensdn.io/repository///images/converts//ubuntu.vmdk.gz
2025-07-24 02:37:24,307 - 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-24 02:37:24,332 - DEBUG - Image has been downloaded to /contrail-test/images/ubuntu.vmdk.gz
2025-07-24 02:37:24,332 - DEBUG - Unzip image
2025-07-24 02:37:24,332 - DEBUG - Image download (local=True) (proxy=None): Execute cmd: gunzip -f /contrail-test/images/ubuntu.vmdk.gz
2025-07-24 02:37:24,344 - DEBUG - Try to create image in user context
2025-07-24 02:37:24,428 - INFO - Deleting VN ctest-dsnat_vn-15706681
2025-07-24 02:37:24,634 - DEBUG - Response for deleting network ()
2025-07-24 02:37:25,930 - 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-24 02:37:25,946 - DEBUG - No XMPP flaps were noticed during the test
2025-07-24 02:37:25,946 - INFO -
2025-07-24 02:37:25,946 - INFO - END TEST : test_dsnat_basic : FAILED[0:00:04]
2025-07-24 02:37:25,946 - INFO - --------------------------------------------------------------------------------
2025-07-24 02:37:25,954 - DEBUG - Hosts: {'nova': ['an-jenkins-deploy-platform-ansible-os-3712-1', 'an-jenkins-deploy-platform-ansible-os-3712-2']}
2025-07-24 02:37:25,954 - INFO - ================================================================================
2025-07-24 02:37:25,954 - INFO - STARTING TEST : test_dsnat_bug_1749695
2025-07-24 02:37:25,954 - 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-24 02:37:27,246 - DEBUG - Nothing to compare xmpp stats {'10.0.0.57': {'10.20.0.17': '0', '10.20.0.129': '0'}, '10.0.0.23': {'10.20.0.129': '0', '10.20.0.17': '0'}} with
2025-07-24 02:37:27,246 - INFO - Initial checks done. Running the testcase now
2025-07-24 02:37:27,246 - INFO -
2025-07-24 02:37:27,246 - INFO - Create VN, enable FABRIC SNAT and verify its routing instance
2025-07-24 02:37:27,541 - DEBUG - Response for create_network : {'network': {'id': '0dfa123f-5a3f-4aa0-b6de-b7c494b0c3cf', 'name': 'ctest-dsnat_vn-02878098', 'tenant_id': '77bbd9c232d24ab298d80594546de96a', 'project_id': '77bbd9c232d24ab298d80594546de96a', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': False, 'mtu': 0, 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestDSNAT-26835159', 'ctest-dsnat_vn-02878098'], 'port_security_enabled': True, 'description': ''}}
2025-07-24 02:37:27,792 - DEBUG - Response for create_subnet : {'subnet': {'id': 'a6d5773a-ebcf-4e8a-9e15-8359d0da6de7', 'name': '', 'tenant_id': '77bbd9c232d24ab298d80594546de96a', 'network_id': '0dfa123f-5a3f-4aa0-b6de-b7c494b0c3cf', 'ip_version': 4, 'cidr': '184.219.99.128/26', 'allocation_pools': [{'start': '184.219.99.130', 'end': '184.219.99.190'}], 'gateway_ip': '184.219.99.129', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '184.219.99.130', 'tags': [], 'project_id': '77bbd9c232d24ab298d80594546de96a'}}
2025-07-24 02:37:27,821 - INFO - Created VN ctest-dsnat_vn-02878098
2025-07-24 02:37:27,835 - DEBUG - VN ctest-dsnat_vn-02878098 UUID is 0dfa123f-5a3f-4aa0-b6de-b7c494b0c3cf
2025-07-24 02:37:28,036 - DEBUG - Requesting: http://10.0.0.19:8082/virtual-network/0dfa123f-5a3f-4aa0-b6de-b7c494b0c3cf
2025-07-24 02:37:28,052 - DEBUG - Requesting: http://10.0.0.19:8082/routing-instance/3a782642-7be5-4607-ade9-4851dcab3787
2025-07-24 02:37:28,372 - DEBUG - Image by name ubuntu-traffic not found
2025-07-24 02:37:28,372 - DEBUG - Installing image ubuntu-traffic
2025-07-24 02:37:28,372 - 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', 'vctmpl': 'ubuntu-traffic.vmtx', 'vcname': 'ubuntu-traffic.vmdk', 'vmdk': 'ubuntu-traffic-disk1.vmdk', 'shrinked_vmdk': "'no'"}
2025-07-24 02:37:28,372 - DEBUG - Image build path http://nexus.opensdn.io/repository///images/converts//ubuntu-traffic.vmdk.gz
2025-07-24 02:37:28,372 - DEBUG - Download image from web http://nexus.opensdn.io/repository///images/converts//ubuntu-traffic.vmdk.gz
2025-07-24 02:37:28,385 - 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-24 02:37:33,573 - DEBUG - Image has been downloaded to /contrail-test/images/ubuntu-traffic.vmdk.gz
2025-07-24 02:37:33,574 - DEBUG - Unzip image
2025-07-24 02:37:33,575 - DEBUG - Image download (local=True) (proxy=None): Execute cmd: gunzip -f /contrail-test/images/ubuntu-traffic.vmdk.gz
2025-07-24 02:37:52,380 - DEBUG - Try to create image in user context
2025-07-24 02:38:04,443 - DEBUG - Image has been created in user context
2025-07-24 02:38:04,443 - DEBUG - Image download (local=True) (proxy=None): Execute cmd: rm -f /contrail-test/images/ubuntu-traffic.vmdk
2025-07-24 02:38:04,725 - DEBUG - Downloaded image has been removed
2025-07-24 02:38:04,747 - DEBUG - Uploaded image status = active
2025-07-24 02:38:05,967 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-3712-1), Zone: (nova:an-jenkins-deploy-platform-ansible-os-3712-1)
2025-07-24 02:38:07,527 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-3712-2), Zone: (nova:an-jenkins-deploy-platform-ansible-os-3712-2)
2025-07-24 02:38:07,527 - INFO - Waiting for VM ctest-TestDSNAT-26835159-76529848 to be up..
2025-07-24 02:38:07,742 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2025-07-24 02:38:12,896 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2025-07-24 02:38:18,028 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2025-07-24 02:38:23,180 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2025-07-24 02:38:28,267 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2025-07-24 02:38:33,365 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2025-07-24 02:38:38,452 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2025-07-24 02:38:43,545 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2025-07-24 02:38:48,641 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2025-07-24 02:38:53,724 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2025-07-24 02:38:58,839 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2025-07-24 02:39:03,931 - DEBUG - VM is in ACTIVE state now
2025-07-24 02:39:03,931 - INFO - VM name : ctest-TestDSNAT-26835159-76529848
2025-07-24 02:39:04,034 - DEBUG - VM ctest-TestDSNAT-26835159-76529848 ID is 9ca193fd-4d17-4364-809c-e9bfd055abaa
2025-07-24 02:39:04,068 - DEBUG - VM ctest-TestDSNAT-26835159-76529848 launched on Node an-jenkins-deploy-platform-ansible-os-3712-1
2025-07-24 02:39:04,176 - DEBUG - Requesting: http://10.0.0.41:8082/virtual-machine/9ca193fd-4d17-4364-809c-e9bfd055abaa
2025-07-24 02:39:04,484 - DEBUG - Requesting: http://10.0.0.41:8082/virtual-machine/9ca193fd-4d17-4364-809c-e9bfd055abaa
2025-07-24 02:39:04,522 - DEBUG - Requesting: http://10.0.0.41:8082/virtual-machine-interface/80a6a1eb-ef4a-46d8-a3fe-900f5c0f3c32
2025-07-24 02:39:07,746 - 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 1007ms')
2025-07-24 02:39:07,746 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestDSNAT-26835159-76529848 failed!
2025-07-24 02:39:07,767 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-26835159:ctest-dsnat_vn-02878098 is 184.219.99.129 and allocation pool is NOT set
2025-07-24 02:39:11,843 - 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-24 02:39:11,843 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestDSNAT-26835159-76529848 failed!
2025-07-24 02:39:11,861 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-26835159:ctest-dsnat_vn-02878098 is 184.219.99.129 and allocation pool is NOT set
2025-07-24 02:39:15,947 - 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-24 02:39:15,947 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestDSNAT-26835159-76529848 failed!
2025-07-24 02:39:15,964 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-26835159:ctest-dsnat_vn-02878098 is 184.219.99.129 and allocation pool is NOT set
2025-07-24 02:39:20,040 - 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-07-24 02:39:20,041 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestDSNAT-26835159-76529848 failed!
2025-07-24 02:39:20,085 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-26835159:ctest-dsnat_vn-02878098 is 184.219.99.129 and allocation pool is NOT set
2025-07-24 02:39:24,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 1017ms')
2025-07-24 02:39:24,160 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestDSNAT-26835159-76529848 failed!
2025-07-24 02:39:24,179 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-26835159:ctest-dsnat_vn-02878098 is 184.219.99.129 and allocation pool is NOT set
2025-07-24 02:39:28,259 - 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-24 02:39:28,259 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestDSNAT-26835159-76529848 failed!
2025-07-24 02:39:28,278 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-26835159:ctest-dsnat_vn-02878098 is 184.219.99.129 and allocation pool is NOT set
2025-07-24 02:39:32,365 - 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-24 02:39:32,365 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestDSNAT-26835159-76529848 failed!
2025-07-24 02:39:32,381 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-26835159:ctest-dsnat_vn-02878098 is 184.219.99.129 and allocation pool is NOT set
2025-07-24 02:39:36,456 - 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 1008ms')
2025-07-24 02:39:36,456 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestDSNAT-26835159-76529848 failed!
2025-07-24 02:39:36,477 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-26835159:ctest-dsnat_vn-02878098 is 184.219.99.129 and allocation pool is NOT set
2025-07-24 02:39:40,553 - 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-24 02:39:40,553 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestDSNAT-26835159-76529848 failed!
2025-07-24 02:39:40,584 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-26835159:ctest-dsnat_vn-02878098 is 184.219.99.129 and allocation pool is NOT set
2025-07-24 02:39:44,679 - 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=9.36 ms\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 1 received, 50% packet loss, time 1030ms\r\nrtt min/avg/max/mdev = 9.360/9.360/9.360/0.000 ms')
2025-07-24 02:39:44,679 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-TestDSNAT-26835159-76529848 passed
2025-07-24 02:39:44,799 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-07-24 02:39:44,799 - DEBUG - Waiting to SSH to VM ctest-TestDSNAT-26835159-76529848, IP 184.219.99.131, Port 22
2025-07-24 02:39:44,869 - 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-24 02:39:44,961 - DEBUG - VM ctest-TestDSNAT-26835159-76529848 is NOT ready for SSH connections, VM status: ACTIVE
2025-07-24 02:39:49,962 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-07-24 02:39:49,962 - DEBUG - Waiting to SSH to VM ctest-TestDSNAT-26835159-76529848, IP 184.219.99.131, Port 22
2025-07-24 02:39:50,019 - 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-24 02:39:50,120 - DEBUG - VM ctest-TestDSNAT-26835159-76529848 is NOT ready for SSH connections, VM status: ACTIVE
2025-07-24 02:39:55,121 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-07-24 02:39:55,121 - DEBUG - Waiting to SSH to VM ctest-TestDSNAT-26835159-76529848, IP 184.219.99.131, Port 22
2025-07-24 02:39:55,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-07-24 02:39:55,285 - DEBUG - VM ctest-TestDSNAT-26835159-76529848 is NOT ready for SSH connections, VM status: ACTIVE
2025-07-24 02:40:00,285 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-07-24 02:40:00,286 - DEBUG - Waiting to SSH to VM ctest-TestDSNAT-26835159-76529848, IP 184.219.99.131, Port 22
2025-07-24 02:40:00,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-07-24 02:40:00,500 - DEBUG - VM ctest-TestDSNAT-26835159-76529848 is NOT ready for SSH connections, VM status: ACTIVE
2025-07-24 02:40:05,501 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-07-24 02:40:05,501 - DEBUG - Waiting to SSH to VM ctest-TestDSNAT-26835159-76529848, IP 184.219.99.131, Port 22
2025-07-24 02:40:05,672 - DEBUG - VM ctest-TestDSNAT-26835159-76529848 is ready for SSH connections
2025-07-24 02:40:05,672 - INFO - Waiting for VM ctest-TestDSNAT-26835159-33265554 to be up..
2025-07-24 02:40:05,788 - DEBUG - VM is in ACTIVE state now
2025-07-24 02:40:05,788 - INFO - VM name : ctest-TestDSNAT-26835159-33265554
2025-07-24 02:40:05,889 - DEBUG - VM ctest-TestDSNAT-26835159-33265554 ID is 17ac1500-cdcc-4211-af00-a4233295b092
2025-07-24 02:40:05,890 - DEBUG - VM ctest-TestDSNAT-26835159-33265554 launched on Node an-jenkins-deploy-platform-ansible-os-3712-2
2025-07-24 02:40:05,990 - DEBUG - Requesting: http://10.0.0.41:8082/virtual-machine/17ac1500-cdcc-4211-af00-a4233295b092
2025-07-24 02:40:06,004 - DEBUG - Requesting: http://10.0.0.41:8082/virtual-machine-interface/8520283d-71c5-423d-80a1-d3feec8e31ae
2025-07-24 02:40:07,233 - 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=7.37 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=0.585 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 = 0.585/3.976/7.368/3.391 ms')
2025-07-24 02:40:07,233 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-TestDSNAT-26835159-33265554 passed
2025-07-24 02:40:07,355 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-07-24 02:40:07,356 - DEBUG - Waiting to SSH to VM ctest-TestDSNAT-26835159-33265554, IP 184.219.99.132, Port 22
2025-07-24 02:40:07,424 - 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-24 02:40:07,537 - DEBUG - VM ctest-TestDSNAT-26835159-33265554 is NOT ready for SSH connections, VM status: ACTIVE
2025-07-24 02:40:12,538 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-07-24 02:40:12,539 - DEBUG - Waiting to SSH to VM ctest-TestDSNAT-26835159-33265554, IP 184.219.99.132, Port 22
2025-07-24 02:40:12,716 - DEBUG - VM ctest-TestDSNAT-26835159-33265554 is ready for SSH connections
2025-07-24 02:40:12,872 - DEBUG - Fetched VN: default-domain:default-project:ip-fabric(9e41e69b-ad51-42d3-9483-13f90253c97e) with subnets None
2025-07-24 02:40:12,924 - DEBUG - Policy np_rules : [rule_sequence = None, rule_uuid = None, direction = <>, protocol = any, src_addresses = [subnet = None, virtual_network = default-domain:ctest-TestDSNAT-26835159:ctest-dsnat_vn-02878098, 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-24 02:40:13,308 - INFO - Attaching policy ctest-test-dsnat-32788089 to vn ctest-dsnat_vn-02878098
2025-07-24 02:40:13,861 - INFO - Attaching policy ctest-test-dsnat-32788089 to vn ip-fabric
2025-07-24 02:40:14,212 - 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.57, gateway password: c0ntrail123
2025-07-24 02:40:14,212 - DEBUG - ping -s 56 -c 3 -W 1 10.20.0.17
2025-07-24 02:40:34,461 - 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=3.56 ms
64 bytes from 10.20.0.17: icmp_req=2 ttl=62 time=0.900 ms
64 bytes from 10.20.0.17: icmp_req=3 ttl=62 time=0.846 ms
--- 10.20.0.17 ping statistics ---
3 packets transmitted, 3 received, 0% packet loss, time 2004ms
rtt min/avg/max/mdev = 0.846/1.771/3.569/1.272 ms
2025-07-24 02:40:34,462 - INFO - Ping to IP 10.20.0.17 from VM ctest-TestDSNAT-26835159-76529848 passed
2025-07-24 02:40:34,604 - 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.57, gateway password: c0ntrail123
2025-07-24 02:40:34,604 - DEBUG - ping -s 56 -c 3 -W 1 10.20.0.17
2025-07-24 02:40:37,662 - 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.53 ms
64 bytes from 10.20.0.17: icmp_req=2 ttl=62 time=0.863 ms
64 bytes from 10.20.0.17: icmp_req=3 ttl=62 time=1.09 ms
--- 10.20.0.17 ping statistics ---
3 packets transmitted, 3 received, 0% packet loss, time 2005ms
rtt min/avg/max/mdev = 0.863/2.163/4.538/1.682 ms
2025-07-24 02:40:37,662 - INFO - Ping to IP 10.20.0.17 from VM ctest-TestDSNAT-26835159-76529848 passed
2025-07-24 02:40:37,662 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-07-24 02:40:37,662 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 3 -W 1 184.219.99.132, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.57, gateway password: c0ntrail123
2025-07-24 02:40:37,662 - DEBUG - ping -s 56 -c 3 -W 1 184.219.99.132
2025-07-24 02:40:40,247 - DEBUG - PING 184.219.99.132 (184.219.99.132) 56(84) bytes of data.
64 bytes from 184.219.99.132: icmp_req=1 ttl=63 time=9.54 ms
64 bytes from 184.219.99.132: icmp_req=2 ttl=63 time=1.19 ms
64 bytes from 184.219.99.132: icmp_req=3 ttl=63 time=1.55 ms
--- 184.219.99.132 ping statistics ---
3 packets transmitted, 3 received, 0% packet loss, time 2004ms
rtt min/avg/max/mdev = 1.194/4.098/9.549/3.857 ms
2025-07-24 02:40:40,247 - INFO - Ping to IP 184.219.99.132 from VM ctest-TestDSNAT-26835159-76529848 passed
2025-07-24 02:40:40,247 - INFO - Dettaching policy ctest-test-dsnat-32788089 from vn ip-fabric
2025-07-24 02:40:40,482 - INFO - Dettaching policy ctest-test-dsnat-32788089 from vn ctest-dsnat_vn-02878098
2025-07-24 02:40:40,744 - INFO - Deleted policy ctest-test-dsnat-32788089
2025-07-24 02:40:40,744 - INFO - Deleting VM ctest-TestDSNAT-26835159-33265554
2025-07-24 02:40:40,831 - INFO - Deleting VM ctest-TestDSNAT-26835159-76529848
2025-07-24 02:40:40,922 - INFO - Deleting VN ctest-dsnat_vn-02878098
2025-07-24 02:40:40,971 - DEBUG - VN 0dfa123f-5a3f-4aa0-b6de-b7c494b0c3cf still in use: Unable to complete operation on network 0dfa123f-5a3f-4aa0-b6de-b7c494b0c3cf. There are one or more ports still in use on the network.
Neutron server returns request_ids: ['req-832fca19-5b72-4363-8d24-4db7662c8b81']
2025-07-24 02:40:40,971 - WARNING - Deleting VN ctest-dsnat_vn-02878098 failed..Will retry
2025-07-24 02:40:43,218 - DEBUG - Response for deleting network ()
2025-07-24 02:40:44,518 - DEBUG - No XMPP flaps were noticed during the test
2025-07-24 02:40:44,519 - INFO - END TEST : test_dsnat_bug_1749695 : PASSED[0:03:19]
2025-07-24 02:40:44,519 - INFO - --------------------------------------------------------------------------------
2025-07-24 02:40:45,312 - INFO - Deleted project: ctest-TestDSNAT-26835159, ID : 77bbd9c2-32d2-4ab2-98d8-0594546de96a
2025-07-24 05:20:53,389 - INFO - Domain Default found not creating
2025-07-24 05:20:53,595 - INFO - Project ctest-TestDSNAT-71174944 not found, creating it
2025-07-24 05:20:54,188 - INFO - Created Project:ctest-TestDSNAT-71174944, ID : 5f5da4fa-1fab-4a9e-861c-d504d9f97b9f
2025-07-24 05:20:56,034 - DEBUG - Services list from nova: [, , , ]
2025-07-24 05:20:56,034 - DEBUG - Hosts: {'nova': ['an-jenkins-deploy-platform-ansible-os-3712-1', 'an-jenkins-deploy-platform-ansible-os-3712-2']}
2025-07-24 05:20:56,034 - INFO - ================================================================================
2025-07-24 05:20:56,034 - INFO - STARTING TEST : test_dsnat_tcp_basic
2025-07-24 05:20:56,034 - 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-24 05:20:57,355 - DEBUG - Skipping xmpp flap check
2025-07-24 05:20:57,355 - INFO - Initial checks done. Running the testcase now
2025-07-24 05:20:57,355 - INFO -
2025-07-24 05:20:57,876 - INFO - Create VN, enable FABRIC SNAT and verify its routing instance
2025-07-24 05:20:58,415 - DEBUG - Response for create_network : {'network': {'id': '508f60f5-8ca0-4328-965d-c9674c992ab4', 'name': 'ctest-dsnat_vn-38414042', 'tenant_id': '5f5da4fa1fab4a9e861cd504d9f97b9f', 'project_id': '5f5da4fa1fab4a9e861cd504d9f97b9f', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': False, 'mtu': 0, 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestDSNAT-71174944', 'ctest-dsnat_vn-38414042'], 'port_security_enabled': True, 'description': ''}}
2025-07-24 05:20:58,884 - DEBUG - Response for create_subnet : {'subnet': {'id': '7bf705ad-c1d9-4835-b7b0-31ed9207feed', 'name': '', 'tenant_id': '5f5da4fa1fab4a9e861cd504d9f97b9f', 'network_id': '508f60f5-8ca0-4328-965d-c9674c992ab4', 'ip_version': 4, 'cidr': '18.212.102.0/26', 'allocation_pools': [{'start': '18.212.102.2', 'end': '18.212.102.62'}], 'gateway_ip': '18.212.102.1', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '18.212.102.2', 'tags': [], 'project_id': '5f5da4fa1fab4a9e861cd504d9f97b9f'}}
2025-07-24 05:20:58,961 - INFO - Created VN ctest-dsnat_vn-38414042
2025-07-24 05:20:59,009 - DEBUG - VN ctest-dsnat_vn-38414042 UUID is 508f60f5-8ca0-4328-965d-c9674c992ab4
2025-07-24 05:20:59,480 - DEBUG - Requesting: http://10.0.0.19:8082/virtual-network/508f60f5-8ca0-4328-965d-c9674c992ab4
2025-07-24 05:21:00,336 - DEBUG - Requesting: http://10.0.0.19:8082/virtual-network/508f60f5-8ca0-4328-965d-c9674c992ab4
2025-07-24 05:21:00,451 - DEBUG - Requesting: http://10.0.0.19:8082/routing-instance/4a5af444-7c08-4930-a18c-8f998cbcede1
2025-07-24 05:21:02,617 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-3712-1), Zone: (nova:an-jenkins-deploy-platform-ansible-os-3712-1)
2025-07-24 05:21:04,746 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-3712-2), Zone: (nova:an-jenkins-deploy-platform-ansible-os-3712-2)
2025-07-24 05:21:04,747 - INFO - Waiting for VM ctest-dsnat-vm1-36312636 to be up..
2025-07-24 05:21:04,862 - DEBUG - VM is still in BUILD state, Expected: ACTIVE
2025-07-24 05:21:09,967 - DEBUG - VM is in ACTIVE state now
2025-07-24 05:21:09,967 - INFO - VM name : ctest-dsnat-vm1-36312636
2025-07-24 05:21:10,065 - DEBUG - VM ctest-dsnat-vm1-36312636 ID is 04480c98-e70f-4305-86ae-48ff173af8f0
2025-07-24 05:21:10,095 - DEBUG - VM ctest-dsnat-vm1-36312636 launched on Node an-jenkins-deploy-platform-ansible-os-3712-1
2025-07-24 05:21:10,196 - DEBUG - Requesting: http://10.0.0.41:8082/virtual-machine/04480c98-e70f-4305-86ae-48ff173af8f0
2025-07-24 05:21:10,532 - DEBUG - Requesting: http://10.0.0.41:8082/virtual-machine/04480c98-e70f-4305-86ae-48ff173af8f0
2025-07-24 05:21:10,576 - DEBUG - Requesting: http://10.0.0.41:8082/virtual-machine-interface/9c700176-9065-4d39-a48c-538ee817a6fb
2025-07-24 05:21:13,796 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 0 received, 100% packet loss, time 1031ms')
2025-07-24 05:21:13,796 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-36312636 failed!
2025-07-24 05:21:13,815 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-71174944:ctest-dsnat_vn-38414042 is 18.212.102.1 and allocation pool is NOT set
2025-07-24 05:21:17,897 - 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 1008ms')
2025-07-24 05:21:17,897 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-36312636 failed!
2025-07-24 05:21:17,921 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-71174944:ctest-dsnat_vn-38414042 is 18.212.102.1 and allocation pool is NOT set
2025-07-24 05:21:21,997 - 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 1008ms')
2025-07-24 05:21:21,998 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-36312636 failed!
2025-07-24 05:21:22,018 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-71174944:ctest-dsnat_vn-38414042 is 18.212.102.1 and allocation pool is NOT set
2025-07-24 05:21:26,126 - 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 1036ms')
2025-07-24 05:21:26,127 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-36312636 failed!
2025-07-24 05:21:26,149 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-71174944:ctest-dsnat_vn-38414042 is 18.212.102.1 and allocation pool is NOT set
2025-07-24 05:21:30,244 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 0 received, 100% packet loss, time 1031ms')
2025-07-24 05:21:30,244 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-36312636 failed!
2025-07-24 05:21:30,266 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-71174944:ctest-dsnat_vn-38414042 is 18.212.102.1 and allocation pool is NOT set
2025-07-24 05:21:34,373 - 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 1027ms')
2025-07-24 05:21:34,374 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-36312636 failed!
2025-07-24 05:21:34,394 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-71174944:ctest-dsnat_vn-38414042 is 18.212.102.1 and allocation pool is NOT set
2025-07-24 05:21:38,474 - 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-07-24 05:21:38,474 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-36312636 failed!
2025-07-24 05:21:38,500 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-71174944:ctest-dsnat_vn-38414042 is 18.212.102.1 and allocation pool is NOT set
2025-07-24 05:21:42,601 - 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-07-24 05:21:42,601 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-36312636 failed!
2025-07-24 05:21:42,624 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-71174944:ctest-dsnat_vn-38414042 is 18.212.102.1 and allocation pool is NOT set
2025-07-24 05:21:46,698 - 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 1004ms')
2025-07-24 05:21:46,699 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-36312636 failed!
2025-07-24 05:21:46,721 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-71174944:ctest-dsnat_vn-38414042 is 18.212.102.1 and allocation pool is NOT set
2025-07-24 05:21:50,789 - 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 1005ms')
2025-07-24 05:21:50,789 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-36312636 failed!
2025-07-24 05:21:50,812 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-71174944:ctest-dsnat_vn-38414042 is 18.212.102.1 and allocation pool is NOT set
2025-07-24 05:21:54,890 - 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 1004ms')
2025-07-24 05:21:54,890 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-36312636 failed!
2025-07-24 05:21:54,912 - DEBUG - Gateway for vn default-domain:ctest-TestDSNAT-71174944:ctest-dsnat_vn-38414042 is 18.212.102.1 and allocation pool is NOT set
2025-07-24 05:21:56,986 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n64 bytes from 169.254.0.3: icmp_seq=1 ttl=63 time=14.4 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=4.25 ms\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 2 received, 0% packet loss, time 1002ms\r\nrtt min/avg/max/mdev = 4.252/9.327/14.403/5.075 ms')
2025-07-24 05:21:56,986 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm1-36312636 passed
2025-07-24 05:21:57,069 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-07-24 05:21:57,069 - DEBUG - Waiting to SSH to VM ctest-dsnat-vm1-36312636, IP 18.212.102.3, Port 22
2025-07-24 05:21:57,138 - 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-24 05:21:57,288 - DEBUG - VM ctest-dsnat-vm1-36312636 is NOT ready for SSH connections, VM status: ACTIVE
2025-07-24 05:22:02,289 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-07-24 05:22:02,289 - DEBUG - Waiting to SSH to VM ctest-dsnat-vm1-36312636, IP 18.212.102.3, Port 22
2025-07-24 05:22:02,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-07-24 05:22:02,499 - DEBUG - VM ctest-dsnat-vm1-36312636 is NOT ready for SSH connections, VM status: ACTIVE
2025-07-24 05:22:07,500 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-07-24 05:22:07,500 - DEBUG - Waiting to SSH to VM ctest-dsnat-vm1-36312636, IP 18.212.102.3, Port 22
2025-07-24 05:22:07,579 - 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-24 05:22:07,702 - DEBUG - VM ctest-dsnat-vm1-36312636 is NOT ready for SSH connections, VM status: ACTIVE
2025-07-24 05:22:12,703 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-07-24 05:22:12,703 - DEBUG - Waiting to SSH to VM ctest-dsnat-vm1-36312636, IP 18.212.102.3, Port 22
2025-07-24 05:22:12,770 - 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-24 05:22:12,934 - DEBUG - VM ctest-dsnat-vm1-36312636 is NOT ready for SSH connections, VM status: ACTIVE
2025-07-24 05:22:17,935 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-07-24 05:22:17,935 - DEBUG - Waiting to SSH to VM ctest-dsnat-vm1-36312636, IP 18.212.102.3, Port 22
2025-07-24 05:22:18,006 - 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-24 05:22:18,117 - DEBUG - VM ctest-dsnat-vm1-36312636 is NOT ready for SSH connections, VM status: ACTIVE
2025-07-24 05:22:23,118 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-07-24 05:22:23,118 - DEBUG - Waiting to SSH to VM ctest-dsnat-vm1-36312636, IP 18.212.102.3, Port 22
2025-07-24 05:22:23,186 - 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-24 05:22:23,293 - DEBUG - VM ctest-dsnat-vm1-36312636 is NOT ready for SSH connections, VM status: ACTIVE
2025-07-24 05:22:28,294 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-07-24 05:22:28,294 - DEBUG - Waiting to SSH to VM ctest-dsnat-vm1-36312636, IP 18.212.102.3, Port 22
2025-07-24 05:22:28,466 - DEBUG - VM ctest-dsnat-vm1-36312636 is ready for SSH connections
2025-07-24 05:22:28,466 - INFO - Waiting for VM ctest-dsnat-vm2-75402075 to be up..
2025-07-24 05:22:28,567 - DEBUG - VM is in ACTIVE state now
2025-07-24 05:22:28,567 - INFO - VM name : ctest-dsnat-vm2-75402075
2025-07-24 05:22:28,669 - DEBUG - VM ctest-dsnat-vm2-75402075 ID is 2b2303f4-ef8a-4d8b-9996-879a2ca3c9d0
2025-07-24 05:22:28,669 - DEBUG - VM ctest-dsnat-vm2-75402075 launched on Node an-jenkins-deploy-platform-ansible-os-3712-2
2025-07-24 05:22:28,767 - DEBUG - Requesting: http://10.0.0.41:8082/virtual-machine/2b2303f4-ef8a-4d8b-9996-879a2ca3c9d0
2025-07-24 05:22:28,780 - DEBUG - Requesting: http://10.0.0.41:8082/virtual-machine-interface/ad31b38b-f5c5-406a-b533-3b4d202c2f65
2025-07-24 05:22:29,986 - 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.89 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=1.99 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 = 1.987/3.440/4.894/1.453 ms')
2025-07-24 05:22:29,987 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-dsnat-vm2-75402075 passed
2025-07-24 05:22:30,068 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-07-24 05:22:30,068 - DEBUG - Waiting to SSH to VM ctest-dsnat-vm2-75402075, IP 18.212.102.4, Port 22
2025-07-24 05:22:30,242 - DEBUG - VM ctest-dsnat-vm2-75402075 is ready for SSH connections
2025-07-24 05:22:30,364 - DEBUG - command output is cat: /tmp/iperf_server_ctest-random-60281334.pid: No such file or directory
kill: usage: kill [-s sigspec | -n signum | -sigspec] pid | jobspec ... or kill -l [sigspec]
2025-07-24 05:22:30,477 - DEBUG - command output is
2025-07-24 05:22:30,477 - INFO - Starting Iperf3 on ctest-dsnat-vm1-36312636, args: --port 6201 --length 1048576 --time 10
2025-07-24 05:22:30,477 - DEBUG - Iperf3 cmd : iperf3 -c 10.20.0.249 --port 6201 --length 1048576 --time 10 1>/tmp/iper3_ctest-random-60281334.log 2>/tmp/iper3_ctest-random-60281334.result
2025-07-24 05:22:30,478 - INFO - Excecuting cmds, ['iperf3 -s --port 6201 1>/tmp/iper3_ctest-random-60281334.log 2>/tmp/iper3_ctest-random-60281334.result'], on server 10.0.0.23
2025-07-24 05:22:30,590 - DEBUG - command output is ['']
2025-07-24 05:22:30,590 - DEBUG - Running remote_cmd, Cmd : iperf3 -c 10.20.0.249 --port 6201 --length 1048576 --time 10 1>/tmp/iper3_ctest-random-60281334.log 2>/tmp/iper3_ctest-random-60281334.result, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.57, gateway password: c0ntrail123
2025-07-24 05:22:30,590 - DEBUG - nohup iperf3 -c 10.20.0.249 --port 6201 --length 1048576 --time 10 1>/tmp/iper3_ctest-random-60281334.log 2>/tmp/iper3_ctest-random-60281334.result & echo $! > /tmp/iperf_client_ctest-random-60281334.pid
2025-07-24 05:22:49,386 - ERROR - Exception occured while running cmds ['iperf3 -c 10.20.0.249 --port 6201 --length 1048576 --time 10 1>/tmp/iper3_ctest-random-60281334.log 2>/tmp/iper3_ctest-random-60281334.result']
2025-07-24 05:22:49,386 - 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-24 05:22:53,069 - DEBUG - command output is /bin/bash: line 1: kill: (65015) - No such process
2025-07-24 05:22:53,188 - DEBUG - command output is
2025-07-24 05:22:53,188 - INFO - Deleting VM ctest-dsnat-vm2-75402075
2025-07-24 05:22:53,290 - INFO - Deleting VM ctest-dsnat-vm1-36312636
2025-07-24 05:22:53,380 - INFO - Deleting VN ctest-dsnat_vn-38414042
2025-07-24 05:22:53,442 - DEBUG - VN 508f60f5-8ca0-4328-965d-c9674c992ab4 still in use: Unable to complete operation on network 508f60f5-8ca0-4328-965d-c9674c992ab4. There are one or more ports still in use on the network.
Neutron server returns request_ids: ['req-0453c13b-bf7a-4885-879e-f4a22539ab24']
2025-07-24 05:22:53,442 - WARNING - Deleting VN ctest-dsnat_vn-38414042 failed..Will retry
2025-07-24 05:22:55,714 - DEBUG - Response for deleting network ()
2025-07-24 05:22:57,040 - ERROR - AttributeError
Python 3.6.8: /usr/bin/python3
Thu Jul 24 05:22:52 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=0x7f6b490688d0>>
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.18', 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.18', 'proto': '6', 'sport': '6201'}
reqd_entries.viewitems undefined
flow_entry_item = {'action': 'DROP', 'bytes': '611', 'd_vrf_id': '2', 'dip': '169.254.0.3', 'dport': '39440', 'drop_reason': 'Unknown', 'flags': ' ACTIVE | EVICTED ', 'gen_id': '1', 'index': '84', '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-24 05:22:57,040 - DEBUG - Skipping xmpp flap check
2025-07-24 05:22:57,040 - INFO -
2025-07-24 05:22:57,040 - INFO - END TEST : test_dsnat_tcp_basic : FAILED[0:02:01]
2025-07-24 05:22:57,040 - INFO - --------------------------------------------------------------------------------
2025-07-24 05:22:57,921 - INFO - Deleted project: ctest-TestDSNAT-71174944, ID : 5f5da4fa-1fab-4a9e-861c-d504d9f97b9f