Merge lp:~vila/ols-store-tests/ols-run-tests into lp:~ubuntuone-pqm-team/ols-store-tests/store-acceptance-tests

[Vincent Ladeuil]

Display log when test_release_snap_successful fails.

Use ols-run-tests to display test names and timings when running on jenkaas.

Properly isolate pip3 by using the virtualenv one rather than the system one.

Display log when test_release_snap_successful fails.

Use ols-run-tests to display test names and timings when running on jenkaas.

Properly isolate pip3 by using the virtualenv one rather than the system one.

[Fabián Ezequiel Gallina (fgallina)]

I like where this is going, in fact I like so much that I'm proposing we have the log on failure for all tests ;)

[Vincent Ladeuil (vila)]

> What if we made this part of the setUp and tearDown process and put it in the base TestCase.

The thing is, this trick requires wrapping the test method itself.

There is no good way (at least I haven't found any so far) that can be achieved "transparently" for all test methods.

If you look at the unittest implementation, you'll see that __call__() calls run() which provides no way to wrap the test method call (search for testMethod there) itself.

Alternatively, this may be be implemented on the TestResult object but that looks brittle (and would require implementing it for all TestResult objects).

This code originated in ols-vms (https://bazaar.launchpad.net/~ubuntuone-hackers/ols-vms/trunk/view/head:/olsvms/tests/__init__.py#L55 but is not used there anymore) and worked well, the constraint of explicitly decorating each test may seem a bit tedious but was worth it (not all tests have a use for that).

While borrowing it I attempted to do just what you suggest but fail.

Come to think of it that should allow the implementation to be simplified (there is no need for a class since there are no level and fmt parameters anymore).

Also note that here, we're not calling logging from any code under test, we only use it as part of the test code.

So this proposal is to activate it where we need it. As such, it's not exposed either where it's not needed.

I'll keep thinking about generalizing it though.

[lp:~vila/ols-store-tests/ols-run-tests]

41. By Vincent Ladeuil on 2017-03-06

Display log on failure for all APITestCase.

[Vincent Ladeuil (vila)]

> What if we made this part of the setUp and tearDown process and put it in the base TestCase.

Take two.

setUp() is too late, this has to happen in __init__.

Last revision does that.

I still think it's a bit too magic (I have a gut feeling this may break in an obscure way in edge cases (parametrized tests for example)) and prefer to decorate the tests that really needs that but let's see how this goes.

[lp:~vila/ols-store-tests/ols-run-tests]

42. By Vincent Ladeuil on 2017-03-06

Hacking from __init__ is too brittle, come back to simpler decorator.

43. By Vincent Ladeuil on 2017-03-06

Remove useless code.

[Fabián Ezequiel Gallina (fgallina)]

LGTM

review: Approve

=== modified file 'Makefile'
--- Makefile	2017-03-01 16:33:48 +0000
+++ Makefile	2017-03-06 11:50:31 +0000
@@ -1,8 +1,8 @@
 # Copyright (C) 2016 Canonical Ltd.
 
 ENV = $(CURDIR)/env
-PIP = pip3
-PYTHON = python3
+PIP = $(ENV)/bin/pip3
+PYTHON = $(ENV)/bin/python3
 VM = store-acceptance-tests
 VSSH = ols-vms shell ${VM}
 TEST_TARGET ?= discover tests/api
@@ -13,7 +13,7 @@
 bootstrap: $(ENV) wheels install-wheels
 
 $(ENV):
-	virtualenv -p $(PYTHON) --clear --system-site-packages $(ENV)
+	virtualenv -p python3 --clear --system-site-packages $(ENV)
 
 wheels:
 	[ -d $(WHEELS_DIR) ] && (cd $(WHEELS_DIR) && bzr pull) || (bzr branch $(WHEELS_BRANCH_URL) $(WHEELS_DIR))

=== modified file 'README'
--- README	2017-03-01 16:40:34 +0000
+++ README	2017-03-06 11:50:31 +0000
@@ -95,4 +95,4 @@
 
 Once there, 'cd' to your mounted working dir and 'make bootstrap'.
 
-ols jenkaas use './run-landing-tests.sh'.
+ols jenkaas uses './run-landing-tests.sh'.

=== modified file 'dependencies.txt'
--- dependencies.txt	2017-03-01 16:33:48 +0000
+++ dependencies.txt	2017-03-06 11:50:31 +0000
@@ -2,6 +2,7 @@
 make
 squashfs-tools
 snapcraft
+python3-ols-tests
 python3-pip
 python3-pymacaroons
 python3-requests

=== modified file 'ols-vms.conf'
--- ols-vms.conf	2017-03-01 16:33:48 +0000
+++ ols-vms.conf	2017-03-06 11:50:31 +0000
@@ -4,4 +4,5 @@
 vm.architecture = amd64
 vm.update = True
 vm.locale = en_US.UTF-8
-vm.packages = @dependencies.txt, bzr
+apt.sources = ppa:ubuntuone/ols-tests
+vm.packages = @dependencies.txt

=== modified file 'run-landing-tests.sh'
--- run-landing-tests.sh	2017-03-01 16:33:48 +0000
+++ run-landing-tests.sh	2017-03-06 11:50:31 +0000
@@ -5,5 +5,4 @@
 SECRETS=~/.config/ols-store-acceptance-tests/secrets
 test -f ${SECRETS} && . ${SECRETS}
 
-make api-tests
-
+PYTHONPATH=`pwd` env/bin/python3 /usr/bin/ols-run-tests

=== modified file 'tests/api/snap/helpers.py'
--- tests/api/snap/helpers.py	2016-08-24 05:32:42 +0000
+++ tests/api/snap/helpers.py	2017-03-06 11:50:31 +0000
@@ -1,6 +1,9 @@
+import functools
 import getpass
 import glob
+import io
 import json
+import logging
 import os
 import shutil
 import subprocess
@@ -9,6 +12,7 @@
 import urllib.parse
 import uuid
 
+
 import requests
 from pymacaroons import Macaroon
 
@@ -159,11 +163,75 @@
         return body.get('upload_id'), version
 
 
+def override_logging(test, stream_out, level=logging.INFO):
+    """Setup a logging handler, restoring the actual handlers after the test.
+
+    This assumes a logging setup where handlers are added to the root logger
+    only.
+
+    :param stream_out: A stream where log messges will be recorded.
+
+    :param level: The logging level to be active during the test.
+
+    :param fmt: The logging format to use during the test.
+
+    """
+    root_logger = logging.getLogger(None)
+    # Using reversed() below ensures we can modify root_logger.handlers as well
+    # as providing the handlers in the right order for cleanups.
+    for handler in reversed(root_logger.handlers):
+        root_logger.removeHandler(handler)
+        test.addCleanup(root_logger.addHandler, handler)
+    # Install the new handler
+    new_handler = logging.StreamHandler(stream_out)
+    test.addCleanup(root_logger.removeHandler, new_handler)
+    root_logger.addHandler(new_handler)
+    # Install the new level, restoring the actual one after the test
+    test.addCleanup(root_logger.setLevel, root_logger.level)
+    root_logger.setLevel(level)
+
+
+def log_on_failure(func):
+    """Decorates a test to display log on failure.
+
+    This requires a 'log_stream' attribute available from the decorated test
+    (which override_logging() provides if called during setUp()).
+
+    With this decoration the test can display the log content when it fails or
+    errors but stay silent otherwise.
+    """
+    @functools.wraps(func)
+    def decorator(*args):
+        test = args[0]
+        display_log = True
+
+        # We need to delay the log acquisition until we attempt to display
+        # it (or we get no content).
+        def delayed_display_log():
+            if display_log:
+                msg = 'Failed test log: >>>\n{}\n<<<'.format(
+                    test.log_stream.getvalue())
+                raise Exception(msg)
+
+        test.addCleanup(delayed_display_log)
+
+        # Run the test without the decoration
+        func(*args)
+        # If it terminates properly, disable log display
+        display_log = False
+    return decorator
+
+
 class APITestCase(unittest.TestCase):
 
     # Do not ever truncate diffs so we don't ever miss response body changes
     maxDiff = None
 
+    def setUp(self):
+        super().setUp()
+        self.log_stream = io.StringIO()
+        override_logging(self, self.log_stream)
+
     def assert_success(self, response, content_type='application/json'):
         self.assertTrue(response.ok, 'Response was: [{}] {}'.format(
             response.status_code, response.content))

=== added file 'tests/api/snap/test_helpers.py'
--- tests/api/snap/test_helpers.py	1970-01-01 00:00:00 +0000
+++ tests/api/snap/test_helpers.py	2017-03-06 11:50:31 +0000
@@ -0,0 +1,70 @@
+import io
+import logging
+import unittest
+
+
+from olstests import (
+    assertions,
+    results,
+)
+
+from tests.api.snap import helpers
+
+
+logger = logging.getLogger(__name__)
+
+
+class TestLogOnFailure(unittest.TestCase):
+
+    def setUp(self):
+        super().setUp()
+        self.result = results.TextResult(io.StringIO(), verbosity=2)
+
+        # We don't care about timing here so we always return 0 which
+        # simplifies matching the expected result
+        def zero(atime):
+            return 0.0
+
+        self.result.convert_delta_to_float = zero
+
+    def test_log_not_displayed(self):
+
+        class Test(helpers.APITestCase):
+
+            @helpers.log_on_failure
+            def test_pass(inner):
+                # Check the test name
+                self.assertTrue(inner.id().endswith('Test.test_pass'))
+                logger.info('pass')
+
+        t = Test('test_pass')
+        t.run(self.result)
+        self.assertEqual('pass\n', t.log_stream.getvalue())
+        self.assertEqual('{} ... OK (0.000 secs)\n'.format(t.id()),
+                         self.result.stream.getvalue())
+        self.assertEqual([], self.result.errors)
+
+    def test_log_displayed(self):
+
+        class Test(helpers.APITestCase):
+
+            @helpers.log_on_failure
+            def test_fail(inner):
+                # Check the test name
+                self.assertTrue(inner.id().endswith('Test.test_fail'))
+                logger.info("I'm broken")
+                inner.fail()
+
+        t = Test('test_fail')
+        t.run(self.result)
+        self.assertEqual("I'm broken\n", t.log_stream.getvalue())
+        # FAILERROR: The test FAIL, the cleanup ERRORs out.
+        self.assertEqual(
+            '{} ... FAILERROR (0.000 secs)\n'.format(t.id()),
+            self.result.stream.getvalue())
+        assertions.assertLength(self, 1, self.result.errors)
+        failing_test, traceback = self.result.errors[0]
+        self.assertIs(t, failing_test)
+        expected = traceback.endswith("Failed test log:"
+                                      " >>>\nI'm broken\n\n<<<\n")
+        self.assertTrue(expected, 'Actual traceback: {}'.format(traceback))

=== modified file 'tests/api/snap/test_snap_release.py'
--- tests/api/snap/test_snap_release.py	2017-03-01 15:54:06 +0000
+++ tests/api/snap/test_snap_release.py	2017-03-06 11:50:31 +0000
@@ -3,18 +3,23 @@
 import time
 import uuid
 
+
 import requests
 
 from .helpers import (
     SCA_ROOT_URL,
     APITestCase,
     authenticate_with_macaroon,
+    log_on_failure,
     upload_snap,
 )
 from .test_register_name import register_name
 from .test_snap_push import push_snap
 
 
+logger = logging.getLogger(__name__)
+
+
 RELEASE_SNAP_RETRY_WAIT = 30
 
 
@@ -41,7 +46,7 @@
         if status_url is not None:
             response = poll_until_processed(status_url)
         else:
-            logging.info(
+            logger.info(
                 'Failed to release: data=%s. Retrying in %s seconds.',
                 data, RELEASE_SNAP_RETRY_WAIT)
             time.sleep(RELEASE_SNAP_RETRY_WAIT)
@@ -61,8 +66,8 @@
 def get_snap_status(status_url):
     response = requests.get(status_url, headers={'Cache-Control': 'no-cache'})
     if not response.ok:
-        logging.error('Failed to get snap status. Response was: [%s] %s',
-                      response.status_code, response.content)
+        logger.error('Failed to get snap status. Response was: [%s] %s',
+                     response.status_code, response.content)
     return response
 
 
@@ -95,7 +100,7 @@
         cls.auth = authenticate_with_macaroon()
 
     def setUp(self):
-        super(SnapReleaseTestCase, self).setUp()
+        super().setUp()
 
         # use same format for package names as snapcraft integration tests
         self.name = 'delete-me-{}'.format(str(uuid.uuid4().int)[:32])
@@ -143,6 +148,7 @@
         }
         self.assertEqual(body, expected)
 
+    @log_on_failure
     def test_release_snap_successful(self):
         response = register_name(self.name, auth=self.auth)
         updown_id, version = upload_snap(self.name)