Check VM's console log before trying to SSH to it.

Due to issue described in related bug report, it seems that it may
happen sometimes that tempest will start trying to ssh to the instance
before ssh key will be really configured in the instance and in such
case it may happened that there will be AuthenticationFailure error
always there. Even if ssh key will be configured properly later during
the test.

To workaround that issue and avoid failures of tests, this patch adds
check if the vm is really booted and ready to ssh. It is done by
checking console log of the VM and looking for specific string "login:"
which appears at least in case of Cirros and Ubuntu images used in our
CI jobs.
In case when such string will not be found, test will continue to run
and will still try to ssh to the instance. So in worst case it may slow
ssh to the instance a bit but shouldn't really have any bad impact on
test as before this patch it would probably also wait similar amount of
time but on trying to SSH to the instance.

Change-Id: I8739f17ec8b05405056fd21f59817de60af12dd8
Related-Bug: #1892861
diff --git a/neutron_tempest_plugin/scenario/base.py b/neutron_tempest_plugin/scenario/base.py
index 402a901..8481edc 100644
--- a/neutron_tempest_plugin/scenario/base.py
+++ b/neutron_tempest_plugin/scenario/base.py
@@ -121,9 +121,11 @@
         if not kwargs.get('security_groups'):
             kwargs['security_groups'] = [{'name': 'default'}]
 
-        client = self.os_primary.servers_client
-        if kwargs.get('availability_zone'):
-            client = self.os_admin.servers_client
+        client = kwargs.pop('client', None)
+        if client is None:
+            client = self.os_primary.servers_client
+            if kwargs.get('availability_zone'):
+                client = self.os_admin.servers_client
 
         server = client.create_server(
             flavorRef=flavor_ref,
@@ -139,6 +141,10 @@
         self.addCleanup(test_utils.call_and_ignore_notfound_exc,
                         client.delete_server,
                         server['server']['id'])
+
+        self.wait_for_server_active(server['server'], client=client)
+        self.wait_for_guest_os_ready(server['server'], client=client)
+
         return server
 
     @classmethod
@@ -252,7 +258,6 @@
             server_kwargs['name'] = server_name
 
         self.server = self.create_server(**server_kwargs)
-        self.wait_for_server_active(self.server['server'])
         self.port = self.client.list_ports(network_id=self.network['id'],
                                            device_id=self.server[
                                                'server']['id'])['ports'][0]
@@ -452,6 +457,28 @@
         self.wait_for_server_status(
             server, constants.SERVER_STATUS_ACTIVE, client)
 
+    def wait_for_guest_os_ready(self, server, client=None):
+        if not CONF.compute_feature_enabled.console_output:
+            LOG.debug('Console output not supported, cannot check if server '
+                      '%s is ready.', server['server']['id'])
+            return
+
+        client = client or self.os_primary.servers_client
+
+        def system_booted():
+            console_output = client.get_console_output(server['id'])['output']
+            for line in console_output.split('\n'):
+                if 'login:' in line.lower():
+                    return True
+            return False
+
+        try:
+            utils.wait_until_true(system_booted, sleep=5)
+        except utils.WaitTimeout:
+            LOG.debug("No correct output in console of server %s found. "
+                      "Guest operating system status can't be checked.",
+                      server['id'])
+
     def check_servers_hostnames(self, servers, timeout=None, log_errors=True,
                                 external_port=None):
         """Compare hostnames of given servers with their names."""
diff --git a/neutron_tempest_plugin/scenario/test_connectivity.py b/neutron_tempest_plugin/scenario/test_connectivity.py
index 1a7468a..66c4789 100644
--- a/neutron_tempest_plugin/scenario/test_connectivity.py
+++ b/neutron_tempest_plugin/scenario/test_connectivity.py
@@ -65,6 +65,7 @@
 
         for vm in vms:
             self.wait_for_server_active(vm['server'])
+            self.wait_for_guest_os_ready(vm['server'])
 
         return vms
 
@@ -231,6 +232,7 @@
             networks=[{'uuid': network['id']}],
             security_groups=[{'name': self.secgroup['name']}])
         self.wait_for_server_active(vm['server'])
+        self.wait_for_guest_os_ready(vm['server'])
 
         vm_port = self.client.list_ports(
             network_id=network['id'], device_id=vm['server']['id'])['ports'][0]
diff --git a/neutron_tempest_plugin/scenario/test_floatingip.py b/neutron_tempest_plugin/scenario/test_floatingip.py
index 6d4d830..8c8d163 100644
--- a/neutron_tempest_plugin/scenario/test_floatingip.py
+++ b/neutron_tempest_plugin/scenario/test_floatingip.py
@@ -417,6 +417,7 @@
             servers.append(server)
         for server in servers:
             self.wait_for_server_active(server)
+            self.wait_for_guest_os_ready(server)
 
         self.fip = self.create_floatingip(port=ports[0])
         self.check_connectivity(self.fip['floating_ip_address'],
diff --git a/neutron_tempest_plugin/scenario/test_internal_dns.py b/neutron_tempest_plugin/scenario/test_internal_dns.py
index d19286c..c620233 100644
--- a/neutron_tempest_plugin/scenario/test_internal_dns.py
+++ b/neutron_tempest_plugin/scenario/test_internal_dns.py
@@ -52,6 +52,7 @@
                 {'name': self.security_groups[-1]['name']}],
             name='leia')
         self.wait_for_server_active(leia['server'])
+        self.wait_for_guest_os_ready(leia['server'])
 
         ssh_client = ssh.Client(
             self.fip['floating_ip_address'],
diff --git a/neutron_tempest_plugin/scenario/test_ipv6.py b/neutron_tempest_plugin/scenario/test_ipv6.py
index 02e2846..741945a 100644
--- a/neutron_tempest_plugin/scenario/test_ipv6.py
+++ b/neutron_tempest_plugin/scenario/test_ipv6.py
@@ -138,6 +138,7 @@
         }
         vm = self.create_server(**server_kwargs)['server']
         self.wait_for_server_active(vm)
+        self.wait_for_guest_os_ready(vm)
         ipv4_port = self.client.list_ports(
             network_id=self.network['id'],
             device_id=vm['id'])['ports'][0]
diff --git a/neutron_tempest_plugin/scenario/test_metadata.py b/neutron_tempest_plugin/scenario/test_metadata.py
index c78ff69..3897183 100644
--- a/neutron_tempest_plugin/scenario/test_metadata.py
+++ b/neutron_tempest_plugin/scenario/test_metadata.py
@@ -126,6 +126,7 @@
         vm = self._create_server_with_network(
             self.network, use_advanced_image=use_advanced_image)
         self.wait_for_server_active(server=vm.server)
+        self.wait_for_guest_os_ready(vm.server)
         self._assert_has_ssh_connectivity(vm.ssh_client)
         interface = self._get_primary_interface(vm.ssh_client)
 
diff --git a/neutron_tempest_plugin/scenario/test_multicast.py b/neutron_tempest_plugin/scenario/test_multicast.py
index b2ea8ae..79f835e 100644
--- a/neutron_tempest_plugin/scenario/test_multicast.py
+++ b/neutron_tempest_plugin/scenario/test_multicast.py
@@ -201,6 +201,7 @@
             security_groups=[{'name': self.secgroup['security_group']['name']}]
         )['server']
         self.wait_for_server_active(server)
+        self.wait_for_guest_os_ready(server)
         port = self.client.list_ports(
             network_id=self.network['id'], device_id=server['id'])['ports'][0]
         server['fip'] = self.create_floatingip(port=port)
diff --git a/neutron_tempest_plugin/scenario/test_port_forwardings.py b/neutron_tempest_plugin/scenario/test_port_forwardings.py
index 4080bca..fb6410c 100644
--- a/neutron_tempest_plugin/scenario/test_port_forwardings.py
+++ b/neutron_tempest_plugin/scenario/test_port_forwardings.py
@@ -70,6 +70,7 @@
                 networks=[{'port': port['id']}])['server']
             server['name'] = name
             self.wait_for_server_active(server)
+            self.wait_for_guest_os_ready(server)
             server['port_forwarding_tcp'] = self.create_port_forwarding(
                 self.fip['id'],
                 internal_port_id=port['id'],
@@ -255,6 +256,7 @@
             name=name, networks=[{'port': port['id']}])['server']
         server['name'] = name
         self.wait_for_server_active(server)
+        self.wait_for_guest_os_ready(server)
 
         # Add a second fixed_ip address to port (same subnet)
         internal_subnet_id = port['fixed_ips'][0]['subnet_id']
diff --git a/neutron_tempest_plugin/scenario/test_qos.py b/neutron_tempest_plugin/scenario/test_qos.py
index 938d2b0..6cd6b25 100644
--- a/neutron_tempest_plugin/scenario/test_qos.py
+++ b/neutron_tempest_plugin/scenario/test_qos.py
@@ -175,6 +175,7 @@
 
         server = self.create_server(**server_kwargs)
         self.wait_for_server_active(server['server'])
+        self.wait_for_guest_os_ready(server['server'])
         self.check_connectivity(self.fip['floating_ip_address'],
                                 CONF.validation.image_ssh_user,
                                 keypair['private_key'])
diff --git a/neutron_tempest_plugin/scenario/test_trunk.py b/neutron_tempest_plugin/scenario/test_trunk.py
index 585af06..03bdd11 100644
--- a/neutron_tempest_plugin/scenario/test_trunk.py
+++ b/neutron_tempest_plugin/scenario/test_trunk.py
@@ -161,6 +161,7 @@
 
     def _configure_vlan_subport(self, vm, vlan_tag, vlan_subnet):
         self.wait_for_server_active(server=vm.server)
+        self.wait_for_guest_os_ready(vm.server)
         self._wait_for_trunk(trunk=vm.trunk)
         self._wait_for_port(port=vm.port)
         self._wait_for_port(port=vm.subport)
@@ -199,6 +200,7 @@
         vm2 = self._create_server_with_trunk_port()
         for vm in (vm1, vm2):
             self.wait_for_server_active(server=vm.server)
+            self.wait_for_guest_os_ready(vm.server)
             self._wait_for_trunk(vm.trunk)
             self._assert_has_ssh_connectivity(vm.ssh_client)
 
@@ -325,6 +327,7 @@
                                 use_advanced_image=use_advanced_image)
         for role in ['migrate', 'connection_test']:
             self.wait_for_server_active(servers[role].server)
+            self.wait_for_guest_os_ready(servers[role].server)
             self._configure_vlan_subport(vm=servers[role],
                                          vlan_tag=vlan_tag,
                                          vlan_subnet=vlan_subnet)
@@ -377,6 +380,7 @@
                                      vlan_subnet=vlan_subnet)
         for vm in vms:
             self.wait_for_server_active(vm.server)
+            self.wait_for_guest_os_ready(vm.server)
 
         # allow ICMP traffic
         sg_rule = self.create_pingable_secgroup_rule(self.security_group['id'])