tests: Improve logging for executed commands

We're seeing failures in a recently added tests,
'ServerTests.test_server_add_remove_volume' from
'openstackclient/tests/functional/compute/v2/test_server.py'. These
failures are likely the result of slow CI nodes, but we don't have
enough information in the CI logs to debug them. Starting logging the
various commands executed in tests so that we can see these logs if and
when tests fail.

Change-Id: I4584dc5e6343fe8c8544431a527d8c3c7e7b3c5b
Signed-off-by: Stephen Finucane <sfinucan@redhat.com>

openstackclient/tests/functional/base.py

@@ -10,6 +10,7 @@
 #    License for the specific language governing permissions and limitations
 #    under the License.
 
+import logging
 import os
 import shlex
 import subprocess
@@ -18,22 +19,30 @@ from tempest.lib.cli import output_parser
 from tempest.lib import exceptions
 import testtools
 
-
 ADMIN_CLOUD = os.environ.get('OS_ADMIN_CLOUD', 'devstack-admin')
+LOG = logging.getLogger(__name__)
 
 
 def execute(cmd, fail_ok=False, merge_stderr=False):
     """Executes specified command for the given action."""
+    LOG.debug('Executing: %s', cmd)
     cmdlist = shlex.split(cmd)
     stdout = subprocess.PIPE
     stderr = subprocess.STDOUT if merge_stderr else subprocess.PIPE
+
     proc = subprocess.Popen(cmdlist, stdout=stdout, stderr=stderr)
-    result, result_err = proc.communicate()
-    result = result.decode('utf-8')
+
+    result_out, result_err = proc.communicate()
+    result_out = result_out.decode('utf-8')
+    LOG.debug('stdout: %s', result_out)
+    LOG.debug('stderr: %s', result_err)
+
     if not fail_ok and proc.returncode != 0:
-        raise exceptions.CommandFailed(proc.returncode, cmd, result,
-                                       result_err)
-    return result
+        raise exceptions.CommandFailed(
+            proc.returncode, cmd, result_out, result_err,
+        )
+
+    return result_out
 
 
 class TestCase(testtools.TestCase):

openstackclient/tests/functional/compute/v2/test_server.py

@@ -1195,19 +1195,19 @@ class ServerTests(common.ComputeTestCase):
     def test_server_add_remove_volume(self):
         volume_wait_for = volume_common.BaseVolumeTests.wait_for_status
 
-        name = uuid.uuid4().hex
+        server_name = uuid.uuid4().hex
         cmd_output = json.loads(self.openstack(
             'server create -f json ' +
             '--network private ' +
             '--flavor ' + self.flavor_name + ' ' +
             '--image ' + self.image_name + ' ' +
             '--wait ' +
-            name
+            server_name
         ))
 
         self.assertIsNotNone(cmd_output['id'])
-        self.assertEqual(name, cmd_output['name'])
-        self.addCleanup(self.openstack, 'server delete --wait ' + name)
+        self.assertEqual(server_name, cmd_output['name'])
+        self.addCleanup(self.openstack, 'server delete --wait ' + server_name)
         server_id = cmd_output['id']
 
         volume_name = uuid.uuid4().hex
@@ -1225,7 +1225,7 @@ class ServerTests(common.ComputeTestCase):
 
         cmd_output = json.loads(self.openstack(
             'server add volume -f json ' +
-            name + ' ' +
+            server_name + ' ' +
             volume_name + ' ' +
             '--tag bar'
         ))
@@ -1237,7 +1237,7 @@ class ServerTests(common.ComputeTestCase):
 
         cmd_output = json.loads(self.openstack(
             'server volume list -f json ' +
-            name
+            server_name
         ))
 
         self.assertEqual(volume_attachment_id, cmd_output[0]['ID'])
@@ -1245,8 +1245,25 @@ class ServerTests(common.ComputeTestCase):
         self.assertEqual(volume_id, cmd_output[0]['Volume ID'])
 
         volume_wait_for('volume', volume_name, 'in-use')
-        self.openstack('server remove volume ' + name + ' ' + volume_name)
+
+        cmd_output = json.loads(self.openstack(
+            'server event list -f json ' +
+            server_name
+        ))
+        self.assertEqual(2, len(cmd_output))
+        self.assertIn('attach_volume', {x['Action'] for x in cmd_output})
+
+        self.openstack(
+            'server remove volume ' + server_name + ' ' + volume_name
+        )
         volume_wait_for('volume', volume_name, 'available')
 
-        raw_output = self.openstack('server volume list ' + name)
+        cmd_output = json.loads(self.openstack(
+            'server event list -f json ' +
+            server_name
+        ))
+        self.assertEqual(3, len(cmd_output))
+        self.assertIn('detach_volume', {x['Action'] for x in cmd_output})
+
+        raw_output = self.openstack('server volume list ' + server_name)
         self.assertEqual('\n', raw_output)