tests: ensure consistent logging format across tests Many of the test modules included calls to 'logging.basicConfig' at global scope in their implementation. This meant that by just importing one of these files, other tests would inherit their logging format. This is typically a bad idea in Python -- modules should not have side effects like this on import.
The format was additionally inconsistent. In some cases we had a "--" prepended to the format, and in others we didn't. The "--" is very useful since it lets developers copy-paste query-test output back into the shell to reproduce an issue. This patch fixes the above by centralizing the logging configuration in a pytest hook that runs prior to all pytests. A few other non-pytest related tools now configure logging in their "main" code which is only triggered when the module is executed directly. I tested that, with this change, logs still show up properly in the .xml output files from 'run-tests.py' as well as when running tests manually from impala-py.test Change-Id: I55ef0214b43f87da2d71804913ba4caa964f789f Reviewed-on: http://gerrit.cloudera.org:8080/11225 Reviewed-by: Philip Zeyliger <[email protected]> Tested-by: Impala Public Jenkins <[email protected]> Project: http://git-wip-us.apache.org/repos/asf/impala/repo Commit: http://git-wip-us.apache.org/repos/asf/impala/commit/30bb0b3d Tree: http://git-wip-us.apache.org/repos/asf/impala/tree/30bb0b3d Diff: http://git-wip-us.apache.org/repos/asf/impala/diff/30bb0b3d Branch: refs/heads/master Commit: 30bb0b3d897e165157dd682846f14b6b8106a87c Parents: 1158883 Author: Todd Lipcon <[email protected]> Authored: Tue Aug 14 16:38:55 2018 -0700 Committer: Todd Lipcon <[email protected]> Committed: Sat Aug 18 04:21:00 2018 +0000 ---------------------------------------------------------------------- tests/common/impala_cluster.py | 1 - tests/common/impala_service.py | 2 -- tests/common/impala_test_suite.py | 1 - tests/common/test_result_verifier.py | 1 - tests/conftest.py | 14 +++++++++++++- tests/metadata/test_hms_integration.py | 5 ----- tests/performance/query_exec_functions.py | 1 - tests/performance/query_executor.py | 1 - tests/performance/scheduler.py | 2 -- tests/performance/workload_runner.py | 2 -- tests/run-tests.py | 3 +++ tests/util/plugin_runner.py | 1 - 12 files changed, 16 insertions(+), 18 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/impala/blob/30bb0b3d/tests/common/impala_cluster.py ---------------------------------------------------------------------- diff --git a/tests/common/impala_cluster.py b/tests/common/impala_cluster.py index d42c450..f04b4b9 100644 --- a/tests/common/impala_cluster.py +++ b/tests/common/impala_cluster.py @@ -32,7 +32,6 @@ from tests.common.impala_service import ( StateStoredService) from tests.util.shell_util import exec_process, exec_process_async -logging.basicConfig(level=logging.ERROR, format='%(threadName)s: %(message)s') LOG = logging.getLogger('impala_cluster') LOG.setLevel(level=logging.DEBUG) http://git-wip-us.apache.org/repos/asf/impala/blob/30bb0b3d/tests/common/impala_service.py ---------------------------------------------------------------------- diff --git a/tests/common/impala_service.py b/tests/common/impala_service.py index 0934f78..b738b8e 100644 --- a/tests/common/impala_service.py +++ b/tests/common/impala_service.py @@ -35,8 +35,6 @@ from RuntimeProfile.ttypes import TRuntimeProfileTree import base64 import zlib -logging.basicConfig(level=logging.ERROR, format='%(asctime)s %(threadName)s: %(message)s', - datefmt='%H:%M:%S') LOG = logging.getLogger('impala_service') LOG.setLevel(level=logging.DEBUG) http://git-wip-us.apache.org/repos/asf/impala/blob/30bb0b3d/tests/common/impala_test_suite.py ---------------------------------------------------------------------- diff --git a/tests/common/impala_test_suite.py b/tests/common/impala_test_suite.py index e7ac7b5..48a53f2 100644 --- a/tests/common/impala_test_suite.py +++ b/tests/common/impala_test_suite.py @@ -79,7 +79,6 @@ from thrift.protocol import TBinaryProtocol # Initializing the logger before conditional imports, since we will need it # for them. -logging.basicConfig(level=logging.INFO, format='-- %(message)s') LOG = logging.getLogger('impala_test_suite') # The ADLS python client isn't downloaded when ADLS isn't the target FS, so do a http://git-wip-us.apache.org/repos/asf/impala/blob/30bb0b3d/tests/common/test_result_verifier.py ---------------------------------------------------------------------- diff --git a/tests/common/test_result_verifier.py b/tests/common/test_result_verifier.py index 2e8bbb1..f071e6b 100644 --- a/tests/common/test_result_verifier.py +++ b/tests/common/test_result_verifier.py @@ -26,7 +26,6 @@ from tests.util.test_file_parser import (join_section_lines, remove_comments, split_section_lines) from tests.util.hdfs_util import NAMENODE -logging.basicConfig(level=logging.INFO, format='%(threadName)s: %(message)s') LOG = logging.getLogger('test_result_verfier') # Special prefix for column values that indicates the actual column value http://git-wip-us.apache.org/repos/asf/impala/blob/30bb0b3d/tests/conftest.py ---------------------------------------------------------------------- diff --git a/tests/conftest.py b/tests/conftest.py index 1d64b6b..f8ca1c7 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -32,8 +32,8 @@ from tests.common.patterns import is_valid_impala_identifier from tests.comparison.db_connection import ImpalaConnection from tests.util.filesystem_utils import FILESYSTEM, ISILON_WEBHDFS_PORT -logging.basicConfig(level=logging.INFO, format='%(threadName)s: %(message)s') LOG = logging.getLogger('test_configuration') +LOG_FORMAT = "-- %(asctime)s %(levelname)-8s %(threadName)s: %(message)s" DEFAULT_CONN_TIMEOUT = 45 DEFAULT_EXPLORATION_STRATEGY = 'core' @@ -50,6 +50,18 @@ if FILESYSTEM == 'isilon': port=ISILON_WEBHDFS_PORT) +def pytest_configure(config): + """ Hook startup of pytest to set up log format. """ + configure_logging() + + +def configure_logging(): + # Use a "--" since most of our tests output SQL commands, and it's nice to + # be able to copy-paste directly from the test output back into a shell to + # try to reproduce a failure. + logging.basicConfig(level=logging.INFO, format=LOG_FORMAT) + + def pytest_addoption(parser): """Adds a new command line options to py.test""" parser.addoption("--exploration_strategy", default=DEFAULT_EXPLORATION_STRATEGY, http://git-wip-us.apache.org/repos/asf/impala/blob/30bb0b3d/tests/metadata/test_hms_integration.py ---------------------------------------------------------------------- diff --git a/tests/metadata/test_hms_integration.py b/tests/metadata/test_hms_integration.py index 0f085c4..3ac5cef 100644 --- a/tests/metadata/test_hms_integration.py +++ b/tests/metadata/test_hms_integration.py @@ -36,11 +36,6 @@ from tests.common.test_dimensions import ( create_uncompressed_text_dimension) from tests.util.hive_utils import HiveDbWrapper, HiveTableWrapper -import logging - -logging.basicConfig(level=logging.INFO, format='%(threadName)s: %(message)s') -LOG = logging.getLogger('test_configuration') - @SkipIfS3.hive @SkipIfADLS.hive @SkipIfIsilon.hive http://git-wip-us.apache.org/repos/asf/impala/blob/30bb0b3d/tests/performance/query_exec_functions.py ---------------------------------------------------------------------- diff --git a/tests/performance/query_exec_functions.py b/tests/performance/query_exec_functions.py index f7d00ec..0366291 100644 --- a/tests/performance/query_exec_functions.py +++ b/tests/performance/query_exec_functions.py @@ -31,7 +31,6 @@ DEFAULT_BEESWAX_PORT = 21000 DEFAULT_HS2_PORT = 21050 DEFAULT_HIVE_HS2_PORT = 10000 -logging.basicConfig(level=logging.INFO, format='[%(name)s] %(threadName)s: %(message)s') LOG = logging.getLogger('query_exec_functions') def get_hs2_hive_cursor(hiveserver, user=None, use_kerberos=False, http://git-wip-us.apache.org/repos/asf/impala/blob/30bb0b3d/tests/performance/query_executor.py ---------------------------------------------------------------------- diff --git a/tests/performance/query_executor.py b/tests/performance/query_executor.py index 1f4bec2..501f34a 100644 --- a/tests/performance/query_executor.py +++ b/tests/performance/query_executor.py @@ -36,7 +36,6 @@ import re from tests.performance.query import Query # Setup logging for this module. -logging.basicConfig(level=logging.INFO, format='[%(name)s] %(threadName)s: %(message)s') LOG = logging.getLogger('query_executor') LOG.setLevel(level=logging.INFO) http://git-wip-us.apache.org/repos/asf/impala/blob/30bb0b3d/tests/performance/scheduler.py ---------------------------------------------------------------------- diff --git a/tests/performance/scheduler.py b/tests/performance/scheduler.py index 8a97dd4..760b331 100644 --- a/tests/performance/scheduler.py +++ b/tests/performance/scheduler.py @@ -28,11 +28,9 @@ from sys import exit from threading import Lock, Thread, Event import threading -logging.basicConfig(level=logging.INFO, format='%(name)s %(threadName)s: %(message)s') LOG = logging.getLogger('scheduler') LOG.setLevel(level=logging.DEBUG) - class Scheduler(object): """Schedules the submission of workloads across one of more clients. http://git-wip-us.apache.org/repos/asf/impala/blob/30bb0b3d/tests/performance/workload_runner.py ---------------------------------------------------------------------- diff --git a/tests/performance/workload_runner.py b/tests/performance/workload_runner.py index a50af9c..9cee7e0 100644 --- a/tests/performance/workload_runner.py +++ b/tests/performance/workload_runner.py @@ -34,8 +34,6 @@ from tests.performance.query_exec_functions import ( execute_using_jdbc) from tests.performance.scheduler import Scheduler -# Setup Logging -logging.basicConfig(level=logging.INFO, format='[%(name)s]: %(message)s') LOG = logging.getLogger('workload_runner') http://git-wip-us.apache.org/repos/asf/impala/blob/30bb0b3d/tests/run-tests.py ---------------------------------------------------------------------- diff --git a/tests/run-tests.py b/tests/run-tests.py index b1a9fdd..78c152b 100755 --- a/tests/run-tests.py +++ b/tests/run-tests.py @@ -24,6 +24,7 @@ # All additional command line options are passed to py.test. from tests.common.impala_cluster import ImpalaCluster from tests.common.impala_service import ImpaladService +from tests.conftest import configure_logging import itertools import json import multiprocessing @@ -224,6 +225,8 @@ def print_metrics(substring): if __name__ == "__main__": + # Ensure that logging is configured for the 'run-test.py' wrapper itself. + configure_logging() exit_on_error = '-x' in sys.argv or '--exitfirst' in sys.argv skip_serial = '--skip-serial' in sys.argv if skip_serial: http://git-wip-us.apache.org/repos/asf/impala/blob/30bb0b3d/tests/util/plugin_runner.py ---------------------------------------------------------------------- diff --git a/tests/util/plugin_runner.py b/tests/util/plugin_runner.py index 0bd8fe6..a0f0d90 100644 --- a/tests/util/plugin_runner.py +++ b/tests/util/plugin_runner.py @@ -22,7 +22,6 @@ import pkgutil PLUGIN_DIR = os.path.join(os.environ['IMPALA_HOME'], 'tests', 'benchmark', 'plugins') # Setup logging for this module. -logging.basicConfig(level=logging.INFO, format='%(filename)s: %(message)s') LOG = logging.getLogger('plugin_runner') LOG.setLevel(level=logging.INFO)
