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 <philip@cloudera.com>
Tested-by: Impala Public Jenkins <impala-public-jenkins@cloudera.com>

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)
 

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)
 

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

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

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,

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

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,

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)
 

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.
 

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')
 
 

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:

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)