IMPALA-10304: Fix log level and format for pytests

Recent testing showed that the pytests are not
respecting the log level and format set in
conftest.py's configure_logging(). It is using
the default log level of WARNING and the
default formatter.

The issue is that logging.basicConfig() is only
effective the first time it is called. The code
in lib/python/impala_py_lib/helpers.py does a
call to logging.basicConfig() at the global
level, and conftest.py imports that file. This
renders the call in configure_logging()
ineffective.

To avoid this type of confusion, logging.basicConfig()
should only be called from the main() functions for
libraries. This removes the call in lib/python/impala_py_lib
(as it is not needed for a library without a main function).
It also fixes up various other locations to move the
logging.basicConfig() call to the main() function.

Testing:
 - Ran the end to end tests and custom cluster tests
 - Confirmed the logging format
 - Added an assert in configure_logging() to test that
   the INFO log level is applied to the root logger.

Change-Id: I5d91b7f910b3606c50bcba4579179a0bc8c20588
Reviewed-on: http://gerrit.cloudera.org:8080/16679
Reviewed-by: Tim Armstrong <tarmstrong@cloudera.com>
Tested-by: Impala Public Jenkins <impala-public-jenkins@cloudera.com>

bin/dump_breakpad_symbols.py

@@ -66,8 +66,6 @@ import tempfile
 from argparse import ArgumentParser
 from collections import namedtuple
 
-logging.basicConfig(level=logging.INFO)
-
 BinarySymbolInfo = namedtuple('BinarySymbolInfo', 'path, debug_path')
 
 
@@ -283,6 +281,7 @@ def process_binary(dump_syms, binary, out_dir):
 
 
 def main():
+  logging.basicConfig(level=logging.INFO)
   args = parse_args()
   dump_syms = args.dump_syms or find_dump_syms_binary()
   assert dump_syms

bin/run-workload.py

@@ -119,7 +119,6 @@ if options.get_password:
   options.password = getpass.getpass()
   options.get_password = None
 
-logging.basicConfig(level=logging.INFO, format='[%(name)s]: %(message)s')
 LOG = logging.getLogger('run-workload')
 
 
@@ -239,6 +238,7 @@ def _validate_options():
       raise RuntimeError("Impalads must be of the form host:port or host.")
 
 if __name__ == "__main__":
+  logging.basicConfig(level=logging.INFO, format='[%(name)s]: %(message)s')
   # Check for badly formed user options.
   _validate_options()
 

bin/start-impala-cluster.py

@@ -42,8 +42,6 @@ from tests.common.impala_cluster import (ImpalaCluster, DEFAULT_BEESWAX_PORT,
     DEFAULT_CATALOGD_JVM_DEBUG_PORT, DEFAULT_IMPALAD_JVM_DEBUG_PORT,
     find_user_processes, run_daemon)
 
-logging.basicConfig(level=logging.ERROR, format="%(asctime)s %(threadName)s: %(message)s",
-    datefmt="%H:%M:%S")
 LOG = logging.getLogger(os.path.splitext(os.path.basename(__file__))[0])
 LOG.setLevel(level=logging.DEBUG)
 
@@ -718,6 +716,8 @@ def validate_options():
 
 
 if __name__ == "__main__":
+  logging.basicConfig(level=logging.ERROR, format="%(asctime)s %(threadName)s: %(message)s",
+    datefmt="%H:%M:%S")
   validate_options()
   if options.docker_network is None:
     cluster_ops = MiniClusterOperations()

lib/python/impala_py_lib/helpers.py

@@ -21,7 +21,6 @@ import os
 import re
 import subprocess
 
-logging.basicConfig()
 LOG = logging.getLogger('impala_lib_python_helpers')
 
 

tests/conftest.py

@@ -68,8 +68,17 @@ 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.
+  #
+  # This call only takes effect if it is the first call to logging.basicConfig().
+  # For example, if some other library calls logging.basicConfig() at the global
+  # level, then importing that library can render this call ineffective.
   logging.basicConfig(level=logging.INFO, format=LOG_FORMAT)
 
+  # Verify that the logging level is set to the correct value.
+  rootLoggerLevel = logging.getLogger().getEffectiveLevel()
+  print("rootLoggerLevel = {0}".format(logging.getLevelName(rootLoggerLevel)))
+  assert(rootLoggerLevel == logging.INFO)
+
 
 def pytest_addoption(parser):
   """Adds a new command line options to py.test"""

tests/shell/util.py

@@ -37,7 +37,6 @@ from tests.common.impala_service import ImpaladService
 from tests.common.impala_test_suite import (IMPALAD_BEESWAX_HOST_PORT,
     IMPALAD_HS2_HOST_PORT, IMPALAD_HS2_HTTP_HOST_PORT)
 
-logging.basicConfig()
 LOG = logging.getLogger('tests/shell/util.py')
 LOG.addHandler(logging.StreamHandler())
 

tests/stress/query_retries_stress_runner.py

@@ -44,7 +44,6 @@ from tests.util.test_file_parser import load_tpc_queries
 
 IMPALA_HOME = os.environ["IMPALA_HOME"]
 
-logging.basicConfig(level=logging.INFO, format='[%(name)s][%(threadName)s]: %(message)s')
 LOG = logging.getLogger('query_retries_stress_test')
 
 
@@ -293,6 +292,7 @@ def parse_args(parser):
 
 
 def main():
+  logging.basicConfig(level=logging.INFO, format='[%(name)s][%(threadName)s]: %(message)s')
   # Parse the command line args.
   parser = ArgumentParser(description="""
 Runs a stress test for transparent query retries. Starts an impala cluster with a