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
diff --git a/.testr.conf b/.testr.conf
index e8f41cd..7e8d028 100644
--- a/.testr.conf
+++ b/.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
diff --git a/tests/base.py b/tests/base.py
index 2d1dd7d..1c3a86f 100755
--- a/tests/base.py
+++ b/tests/base.py
@@ -28,10 +28,12 @@
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.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 @@
'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 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 @@
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
- if os.environ.get('OS_LOG_LEVEL') == 'DEBUG':
- log_level = logging.DEBUG
- elif os.environ.get('OS_LOG_LEVEL') == 'INFO':
- 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'))
+ self._log_stream = StringIO()
+ self.addOnException(self.attachLogs)
+ else:
+ self._log_stream = sys.stdout
- # NOTE(notmorgan): Extract logging overrides for specific libraries
- # from the OS_LOG_DEFAULTS env and create FakeLogger fixtures for
- # each. This is used to limit the output during test runs from
- # libraries that zuul depends on such as gear.
+ handler = logging.StreamHandler(self._log_stream)
+ formatter = logging.Formatter('%(asctime)s %(name)-32s '
+ '%(levelname)-8s %(message)s')
+ 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(
- name=name,
- level=level,
- format='%(asctime)s %(name)-32s '
- '%(levelname)-8s %(message)s'))
+ logger = logging.getLogger(name)
+ logger.setLevel(level)
+ logger.addHandler(handler)
+ logger.propagate = False
except ValueError:
# NOTE(notmorgan): Invalid format of the log default,
# skip and don't try and apply a logger for the
diff --git a/tests/unit/test_clonemapper.py b/tests/unit/test_clonemapper.py
index b7814f8..bd8c8b0 100644
--- a/tests/unit/test_clonemapper.py
+++ b/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):
diff --git a/tests/unit/test_cloner.py b/tests/unit/test_cloner.py
index 67b5303..2cdc826 100644
--- a/tests/unit/test_cloner.py
+++ b/tests/unit/test_cloner.py
@@ -26,10 +26,6 @@
from tests.base import ZuulTestCase
-logging.basicConfig(level=logging.DEBUG,
- format='%(asctime)s %(name)-32s '
- '%(levelname)-8s %(message)s')
-
class TestCloner(ZuulTestCase):
diff --git a/tests/unit/test_cloner_cmd.py b/tests/unit/test_cloner_cmd.py
index 9cbb5b8..2d8747f 100644
--- a/tests/unit/test_cloner_cmd.py
+++ b/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):
diff --git a/tests/unit/test_merger_repo.py b/tests/unit/test_merger_repo.py
index 5062c14..f815344 100644
--- a/tests/unit/test_merger_repo.py
+++ b/tests/unit/test_merger_repo.py
@@ -23,10 +23,6 @@
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):
diff --git a/tests/unit/test_openstack.py b/tests/unit/test_openstack.py
index 175b4bd..d0c7ab2 100644
--- a/tests/unit/test_openstack.py
+++ b/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
diff --git a/tests/unit/test_requirements.py b/tests/unit/test_requirements.py
index 1ea0b2e..7e578cf 100644
--- a/tests/unit/test_requirements.py
+++ b/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"""
diff --git a/tests/unit/test_scheduler.py b/tests/unit/test_scheduler.py
index 86c7c2d..55c56d4 100755
--- a/tests/unit/test_scheduler.py
+++ b/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 @@
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'
diff --git a/tests/unit/test_v3.py b/tests/unit/test_v3.py
index 9034bf7..31410fb 100644
--- a/tests/unit/test_v3.py
+++ b/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
diff --git a/tests/unit/test_zuultrigger.py b/tests/unit/test_zuultrigger.py
index b36e5a4..5d9c6e0 100644
--- a/tests/unit/test_zuultrigger.py
+++ b/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'
diff --git a/tox.ini b/tox.ini
index 58acf09..b7d89d1 100644
--- a/tox.ini
+++ b/tox.ini
@@ -9,8 +9,7 @@
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
+passenv = ZUUL_TEST_ROOT OS_STDOUT_CAPTURE OS_STDERR_CAPTURE OS_LOG_CAPTURE OS_LOG_DEFAULTS
usedevelop = True
install_command = pip install {opts} {packages}
deps = -r{toxinidir}/requirements.txt