Tests: store debug logs on error

Rather than using the FakeLogger fixture, which always attaches
the log stream as a detail, use standard loggers that output to
a stringio, and then, only if a test fails, attach the full
log as a detail.

This allows us to report full debug-level logs for failing tests
in the gate (which normally has a limit on how large subunit files
can be).

Change-Id: I9e6509b7b69838d29582b040ef22f1d66010d45e

.testr.conf

@@ -1,4 +1,4 @@
 [DEFAULT]
-test_command=OS_LOG_LEVEL=${OS_LOG_LEVEL:-INFO} OS_STDOUT_CAPTURE=${OS_STDOUT_CAPTURE:-1} OS_STDERR_CAPTURE=${OS_STDERR_CAPTURE:-1} OS_LOG_CAPTURE=${OS_LOG_CAPTURE:-1} OS_LOG_DEFAULTS=${OS_LOG_DEFAULTS:-""} ${PYTHON:-python} -m subunit.run discover -t ./ ${OS_TEST_PATH:-./tests/unit} $LISTOPT $IDOPTION
+test_command=OS_STDOUT_CAPTURE=${OS_STDOUT_CAPTURE:-1} OS_STDERR_CAPTURE=${OS_STDERR_CAPTURE:-1} OS_LOG_CAPTURE=${OS_LOG_CAPTURE:-1} OS_LOG_DEFAULTS=${OS_LOG_DEFAULTS:-""} ${PYTHON:-python} -m subunit.run discover -t ./ ${OS_TEST_PATH:-./tests/unit} $LISTOPT $IDOPTION
 test_id_option=--load-list $IDFILE
 test_list_option=--list

tests/base.py

@@ -28,10 +28,12 @@ import re
 import select
 import shutil
 from six.moves import reload_module
+from six import StringIO
 import socket
 import string
 import subprocess
 import swiftclient
+import sys
 import tempfile
 import threading
 import time
@@ -43,6 +45,8 @@ import kazoo.client
 import kazoo.exceptions
 import statsd
 import testtools
+import testtools.content
+import testtools.content_type
 from git.exc import NoSuchPathError
 
 import zuul.driver.gerrit.gerritsource as gerritsource
@@ -64,10 +68,6 @@ FIXTURE_DIR = os.path.join(os.path.dirname(__file__),
                            'fixtures')
 USE_TEMPDIR = True
 
-logging.basicConfig(level=logging.DEBUG,
-                    format='%(asctime)s %(name)-32s '
-                    '%(levelname)-8s %(message)s')
-
 
 def repack_repo(path):
     cmd = ['git', '--git-dir=%s/.git' % path, 'repack', '-afd']
@@ -1048,6 +1048,20 @@ class ChrootedKazooFixture(fixtures.Fixture):
 class BaseTestCase(testtools.TestCase):
     log = logging.getLogger("zuul.test")
 
+    def attachLogs(self, *args):
+        def reader():
+            self._log_stream.seek(0)
+            while True:
+                x = self._log_stream.read(4096)
+                if not x:
+                    break
+                yield x.encode('utf8')
+        content = testtools.content.content_from_reader(
+            reader,
+            testtools.content_type.UTF8_TEXT,
+            False)
+        self.addDetail('logging', content)
+
     def setUp(self):
         super(BaseTestCase, self).setUp()
         test_timeout = os.environ.get('OS_TEST_TIMEOUT', 0)
@@ -1069,40 +1083,37 @@ class BaseTestCase(testtools.TestCase):
             self.useFixture(fixtures.MonkeyPatch('sys.stderr', stderr))
         if (os.environ.get('OS_LOG_CAPTURE') == 'True' or
             os.environ.get('OS_LOG_CAPTURE') == '1'):
-            log_level = logging.DEBUG
+            self._log_stream = StringIO()
-            if os.environ.get('OS_LOG_LEVEL') == 'DEBUG':
+            self.addOnException(self.attachLogs)
-                log_level = logging.DEBUG
+        else:
-            elif os.environ.get('OS_LOG_LEVEL') == 'INFO':
+            self._log_stream = sys.stdout
-                log_level = logging.INFO
-            elif os.environ.get('OS_LOG_LEVEL') == 'WARNING':
-                log_level = logging.WARNING
-            elif os.environ.get('OS_LOG_LEVEL') == 'ERROR':
-                log_level = logging.ERROR
-            elif os.environ.get('OS_LOG_LEVEL') == 'CRITICAL':
-                log_level = logging.CRITICAL
-            self.useFixture(fixtures.FakeLogger(
-                level=log_level,
-                format='%(asctime)s %(name)-32s '
-                '%(levelname)-8s %(message)s'))
 
-        # NOTE(notmorgan): Extract logging overrides for specific libraries
+        handler = logging.StreamHandler(self._log_stream)
-        # from the OS_LOG_DEFAULTS env and create FakeLogger fixtures for
+        formatter = logging.Formatter('%(asctime)s %(name)-32s '
-        # each. This is used to limit the output during test runs from
+                                      '%(levelname)-8s %(message)s')
-        # libraries that zuul depends on such as gear.
+        handler.setFormatter(formatter)
+
+        logger = logging.getLogger()
+        logger.setLevel(logging.DEBUG)
+        logger.addHandler(handler)
+
+        # NOTE(notmorgan): Extract logging overrides for specific
+        # libraries from the OS_LOG_DEFAULTS env and create loggers
+        # for each. This is used to limit the output during test runs
+        # from libraries that zuul depends on such as gear.
         log_defaults_from_env = os.environ.get(
             'OS_LOG_DEFAULTS',
-            'git.cmd=INFO,kazoo.client=INFO')
+            'git.cmd=INFO,kazoo.client=WARNING,gear=INFO')
 
         if log_defaults_from_env:
             for default in log_defaults_from_env.split(','):
                 try:
                     name, level_str = default.split('=', 1)
                     level = getattr(logging, level_str, logging.DEBUG)
-                    self.useFixture(fixtures.FakeLogger(
+                    logger = logging.getLogger(name)
-                        name=name,
+                    logger.setLevel(level)
-                        level=level,
+                    logger.addHandler(handler)
-                        format='%(asctime)s %(name)-32s '
+                    logger.propagate = False
-                               '%(levelname)-8s %(message)s'))
                 except ValueError:
                     # NOTE(notmorgan): Invalid format of the log default,
                     # skip and don't try and apply a logger for the

tests/unit/test_clonemapper.py

@@ -13,14 +13,9 @@
 # License for the specific language governing permissions and limitations
 # under the License.
 
-import logging
 import testtools
 from zuul.lib.clonemapper import CloneMapper
 
-logging.basicConfig(level=logging.DEBUG,
-                    format='%(asctime)s %(name)-17s '
-                    '%(levelname)-8s %(message)s')
-
 
 class TestCloneMapper(testtools.TestCase):
 

tests/unit/test_cloner.py

@@ -26,10 +26,6 @@ import zuul.lib.cloner
 
 from tests.base import ZuulTestCase
 
-logging.basicConfig(level=logging.DEBUG,
-                    format='%(asctime)s %(name)-32s '
-                    '%(levelname)-8s %(message)s')
-
 
 class TestCloner(ZuulTestCase):
 

tests/unit/test_cloner_cmd.py

@@ -12,16 +12,11 @@
 # License for the specific language governing permissions and limitations
 # under the License.
 
-import logging
 import os
 
 import testtools
 import zuul.cmd.cloner
 
-logging.basicConfig(level=logging.DEBUG,
-                    format='%(asctime)s %(name)-32s '
-                    '%(levelname)-8s %(message)s')
-
 
 class TestClonerCmdArguments(testtools.TestCase):
 

tests/unit/test_merger_repo.py

@@ -23,10 +23,6 @@ import git
 from zuul.merger.merger import Repo
 from tests.base import ZuulTestCase
 
-logging.basicConfig(level=logging.DEBUG,
-                    format='%(asctime)s %(name)-32s '
-                    '%(levelname)-8s %(message)s')
-
 
 class TestMergerRepo(ZuulTestCase):
 

tests/unit/test_openstack.py

@@ -14,14 +14,8 @@
 # License for the specific language governing permissions and limitations
 # under the License.
 
-import logging
-
 from tests.base import AnsibleZuulTestCase
 
-logging.basicConfig(level=logging.DEBUG,
-                    format='%(asctime)s %(name)-32s '
-                    '%(levelname)-8s %(message)s')
-
 
 class TestOpenStack(AnsibleZuulTestCase):
     # A temporary class to experiment with how openstack can use

tests/unit/test_requirements.py

@@ -14,15 +14,10 @@
 # License for the specific language governing permissions and limitations
 # under the License.
 
-import logging
 import time
 
 from tests.base import ZuulTestCase
 
-logging.basicConfig(level=logging.DEBUG,
-                    format='%(asctime)s %(name)-32s '
-                    '%(levelname)-8s %(message)s')
-
 
 class TestRequirementsApprovalNewerThan(ZuulTestCase):
     """Requirements with a newer-than comment requirement"""

tests/unit/test_scheduler.py

@@ -15,7 +15,6 @@
 # under the License.
 
 import json
-import logging
 import os
 import re
 import shutil
@@ -36,10 +35,6 @@ from tests.base import (
     repack_repo,
 )
 
-logging.basicConfig(level=logging.DEBUG,
-                    format='%(asctime)s %(name)-32s '
-                    '%(levelname)-8s %(message)s')
-
 
 class TestScheduler(ZuulTestCase):
     tenant_config_file = 'config/single-tenant/main.yaml'

tests/unit/test_v3.py

@@ -14,16 +14,11 @@
 # License for the specific language governing permissions and limitations
 # under the License.
 
-import logging
 import os
 import textwrap
 
 from tests.base import AnsibleZuulTestCase
 
-logging.basicConfig(level=logging.DEBUG,
-                    format='%(asctime)s %(name)-32s '
-                    '%(levelname)-8s %(message)s')
-
 
 class TestMultipleTenants(AnsibleZuulTestCase):
     # A temporary class to hold new tests while others are disabled

tests/unit/test_zuultrigger.py

@@ -14,14 +14,8 @@
 # License for the specific language governing permissions and limitations
 # under the License.
 
-import logging
-
 from tests.base import ZuulTestCase
 
-logging.basicConfig(level=logging.DEBUG,
-                    format='%(asctime)s %(name)-32s '
-                    '%(levelname)-8s %(message)s')
-
 
 class TestZuulTriggerParentChangeEnqueued(ZuulTestCase):
     tenant_config_file = 'config/zuultrigger/parent-change-enqueued/main.yaml'

tox.ini

@@ -9,8 +9,7 @@ setenv = STATSD_HOST=127.0.0.1
          STATSD_PORT=8125
          VIRTUAL_ENV={envdir}
          OS_TEST_TIMEOUT=60
-         OS_LOG_DEFAULTS={env:OS_LOG_DEFAULTS:gear=WARNING}
+passenv = ZUUL_TEST_ROOT OS_STDOUT_CAPTURE OS_STDERR_CAPTURE OS_LOG_CAPTURE OS_LOG_DEFAULTS
-passenv = ZUUL_TEST_ROOT OS_STDOUT_CAPTURE OS_STDERR_CAPTURE OS_LOG_CAPTURE
 usedevelop = True
 install_command = pip install {opts} {packages}
 deps = -r{toxinidir}/requirements.txt