Fix logging (#96)

Author: rweigel

hapiclient/hapi.py

@@ -210,13 +210,14 @@ def hapi(*args, **kwargs):
             # TODO: Consider warning.
             STOP = STOP + 'Z'
 
-    # Override defaults
-    opts = setopts(hapiopts(), kwargs)
 
-    msg = "logging keyword must be True, False, or a file-like object"
-    assert (isinstance(opts['logging'], bool) or hasattr(opts['logging'], 'write')), msg
+    if 'logging' in kwargs and not isinstance(kwargs['logging'], bool):
+        raise ValueError("logging keyword must be True or False")
+
+    configure_logging(kwargs.get('logging', None))
 
-    configure_logging(opts)
+    # Override defaults
+    opts = setopts(hapiopts(), kwargs)
 
     assert (opts['cache'] in [True, False]), "cache keyword must be True of False"
     assert (opts['usecache'] in [True, False]), "usecache keyword must be True of False"

hapiclient/log.py

@@ -5,22 +5,16 @@
 _INTERNAL_HANDLER_ATTR = "_hapiclient_internal_handler"
 _INTERNAL_LEVEL_ATTR = "_hapiclient_internal_level"
 
-# Disable propagation and add NullHandler by default so hapiclient
-# is silent unless explicitly configured by user. This is the standard
-# practice for library loggers.
+# Disable propagation by default so hapiclient logs don't bubble up
+# to root logger (e.g., pytest's logger). Can be re-enabled by user.
 _logger.propagate = False
-_logger.setLevel(_logging.NOTSET)
-if not _logger.handlers:
-    _null_handler = _logging.NullHandler()
-    setattr(_null_handler, _INTERNAL_HANDLER_ATTR, True)
-    _logger.addHandler(_null_handler)
 
 
-def configure_logging(opts):
+def configure_logging(logging):
     """Configure the hapiclient logger based on opts['logging'].
 
     If the hapiclient logger has been configured externally (level != NOTSET
-    or handlers present), the logging kwarg.
+    or handlers present), the logging kwarg is ignored and a warning is logged.
     """
     has_user_level = _logger.level != _logging.NOTSET and \
                      _logger.level != getattr(_logger, _INTERNAL_LEVEL_ATTR, None)
@@ -29,7 +23,7 @@ def configure_logging(opts):
         for handler in _logger.handlers
     )
 
-    if opts['logging']:
+    if logging is True:
         _logger.setLevel(_logging.INFO)
         setattr(_logger, _INTERNAL_LEVEL_ATTR, _logging.INFO)
         _logger.propagate = False
@@ -39,13 +33,16 @@ def configure_logging(opts):
             _handler.setFormatter(_logging.Formatter("%(message)s"))
             setattr(_handler, _INTERNAL_HANDLER_ATTR, True)
             _logger.addHandler(_handler)
-    else:
+    if logging is False:
         if has_user_level or has_user_handlers:
-            # Don't log when logging is disabled - would cause output during tests
-            pass
+            from .util import warning
+            if has_user_handlers:
+                warning("Ignoring logging=False because standard Python logger for 'hapiclient' already configured with handlers.")
+            else:
+                warning("Ignoring logging=False because standard Python logger for 'hapiclient' already configured with log_level != NOTSET.")
         else:
-            _logger.setLevel(_logging.NOTSET)
-            setattr(_logger, _INTERNAL_LEVEL_ATTR, _logging.NOTSET)
+            _logger.setLevel(_logging.WARNING)
+            setattr(_logger, _INTERNAL_LEVEL_ATTR, _logging.WARNING)
 
 
 def log(msg, opts=None):

hapiclient/util.py

@@ -1,4 +1,4 @@
-from hapiclient.log import log, configure_logging
+from hapiclient.log import log
 
 
 def setopts(defaults, given):
@@ -148,7 +148,7 @@ def prefix():
         import platform
         prefix = "\x1b[31mHAPIWarning:\x1b[0m "
         if platform.system() == 'Windows' and pythonshell() == 'shell':
-            prefix = "HAPIWarning: "        
+            prefix = "HAPIWarning: "
 
         return prefix
 

misc/hapi_logging_demo.py

@@ -1,3 +1,5 @@
+import logging
+
 from hapiclient import hapi
 
 server     = 'http://hapi-server.org/servers/TestData2.0/hapi'
@@ -6,35 +8,57 @@
 start      = '1970-01-01T00:00:00'
 stop       = '1970-01-01T00:01:00'
 
-method = 3
-
-# 1. Log to console using logging keyword (legacy)
-if method == 1:
-  data, meta = hapi(server, dataset, parameters, start, stop, logging=True)
 
-# 2. Log to console using Python's standard logging module
-if method == 2:
-  import logging
-  logger = logging.getLogger("hapiclient")
-  logger.setLevel(logging.INFO)
-  handler = logging.StreamHandler()
-  formatter = logging.Formatter("%(asctime)s [%(name)s] %(message)s", datefmt="%Y-%m-%dT%H:%M:%S")
-  formatter.default_msec_format = '%s.%03d'
-  handler.setFormatter(formatter)
-  logger.addHandler(handler)
-  data, meta = hapi(server, dataset, parameters, start, stop)
-
-# 3. Log to a file using Python's standard logging module
-if method == 3:
-  import logging
+def reset_hapiclient_logging():
   logger = logging.getLogger("hapiclient")
-  logger.setLevel(logging.INFO)
-  handler = logging.FileHandler("hapi_logging_demo.log")
-  formatter = logging.Formatter("%(asctime)s %(message)s", datefmt="%Y-%m-%dT%H:%M:%S")
-  formatter.default_msec_format = '%s.%03d'
-  handler.setFormatter(formatter)
-  logger.addHandler(handler)
-  data, meta = hapi(server, dataset, parameters, start, stop)
-
-  # Note that logging keyword is ignored when using Python's standard logging module.
-  data, meta = hapi(server, dataset, parameters, start, stop, logging=False)
+  for handler in list(logger.handlers):
+    logger.removeHandler(handler)
+    handler.close()
+  logger.setLevel(logging.NOTSET)
+  logger.propagate = False
+  if hasattr(logger, "_hapiclient_internal_level"):
+    delattr(logger, "_hapiclient_internal_level")
+
+
+for method in range(1, 7):
+
+  reset_hapiclient_logging()
+
+  print(80*"-")
+  print("Method {}: ".format(method))
+  print(80*"-")
+
+  # 1. Log to console using logging keyword (legacy)
+  if 1 <= method <= 3:
+    if method == 1:
+      # No logging kwarg, so no logging
+      data, meta = hapi(server, dataset, parameters, start, stop)
+    if method == 2:
+      # Use internal logging because logging=True and no standard logging handlers defined
+      data, meta = hapi(server, dataset, parameters, start, stop, logging=True)
+    if method == 3:
+      # No logging because logging=False and no standard logging handlers defined
+      data, meta = hapi(server, dataset, parameters, start, stop, logging=False)
+
+  # 2. Log to console using Python's standard logging module
+  if 4 <= method <= 6:
+    import logging
+    logger = logging.getLogger("hapiclient")
+    logger.setLevel(logging.INFO)
+    handler = logging.StreamHandler()
+    formatter = logging.Formatter("%(asctime)s [%(name)s] %(message)s", datefmt="%Y-%m-%dT%H:%M:%S")
+    formatter.default_msec_format = '%s.%03d'
+    handler.setFormatter(formatter)
+    logger.addHandler(handler)
+
+    if method == 4:
+      # Use standard logging because defined
+      data, meta = hapi(server, dataset, parameters, start, stop)
+    if method == 5:
+      # Use standard logging because defined
+      data, meta = hapi(server, dataset, parameters, start, stop, logging=True)
+    if method == 6:
+      # Warning because standard logging defined but logging=False
+      data, meta = hapi(server, dataset, parameters, start, stop, logging=False)
+
+  print(80*"-" + "\n")

test/test_logging.py

@@ -12,8 +12,11 @@
 def _reset_logger():
   """Remove all handlers and reset level on the hapiclient logger."""
   logger = logging.getLogger("hapiclient")
-  logger.handlers.clear()
+  for handler in list(logger.handlers):
+    logger.removeHandler(handler)
+    handler.close()
   logger.setLevel(logging.NOTSET)
+  logger.propagate = False
   if hasattr(logger, "_hapiclient_internal_level"):
     delattr(logger, "_hapiclient_internal_level")
 
@@ -87,30 +90,6 @@ def test_logging_false_ignored_when_externally_configured(self):
     assert 'Running hapi.py version' in output
 
 
-class TestStandardLoggingFile:
-  """Method 4: Standard logging with FileHandler."""
-
-  def setup_method(self):
-    _reset_logger()
-
-  def teardown_method(self):
-    _reset_logger()
-
-  def test_logs_to_file(self, tmp_path):
-    logfile = tmp_path / "hapiclient.log"
-    logger = logging.getLogger("hapiclient")
-    logger.setLevel(logging.INFO)
-    handler = logging.FileHandler(str(logfile))
-    handler.setFormatter(logging.Formatter("%(asctime)s %(message)s"))
-    logger.addHandler(handler)
-
-    data, meta = hapi(server, dataset, parameters, start, stop)
-    handler.close()
-
-    content = logfile.read_text()
-    assert 'Running hapi.py version' in content
-
-
 class TestLoggingKeywordFalse:
   """Default: logging=False suppresses INFO messages."""
 
@@ -129,9 +108,6 @@ def test_no_info_output(self, capsys):
 
 if __name__ == "__main__":
     import pytest
-    #pytest.main([__file__])
     pytest.main([__file__ + "::TestLoggingKeywordFalse", "-v"])
     pytest.main([__file__ + "::TestLoggingKeywordTrue", "-v"])
-    pytest.main([__file__ + "::TestLoggingKeywordFileObject", "-v"])
     pytest.main([__file__ + "::TestStandardLoggingConsole", "-v"])
-    pytest.main([__file__ + "::TestStandardLoggingFile", "-v"])