Merge pull request #658 from mapbox/better-logging

Keep rasterio's cpl error handler in place
rasterio · Apr 11, 2016 · 5d56266 · 5d56266
2 parents b539fc7 + af06b9a
commit 5d56266
Show file tree

Hide file tree

Showing 4 changed files with 60 additions and 42 deletions.
diff --git a/rasterio/__init__.py b/rasterio/__init__.py
@@ -3,6 +3,12 @@
 
 from collections import namedtuple
 import logging
+try:
+    from logging import NullHandler
+except ImportError:
+    class NullHandler(logging.Handler):
+        def emit(self, record):
+            pass
 
 from rasterio._base import (
     eval_window, window_shape, window_index, gdal_version)
@@ -26,11 +32,12 @@
 __version__ = "0.34.0"
 __gdal_version__ = gdal_version()
 
-log = logging.getLogger('rasterio')
-class NullHandler(logging.Handler):
-    def emit(self, record):
-        pass
-log.addHandler(NullHandler())
+# Rasterio attaches NullHandler to the 'rasterio' and 'GDAL' loggers.
+# See https://docs.python.org/2/howto/logging.html#configuring-logging-for-a-library
+# Applications will need to attach their own handlers in order to
+# see messages. See rasterio/rio/main.py for an example.
+log = logging.getLogger('rasterio').addHandler(NullHandler())
+log = logging.getLogger('GDAL').addHandler(NullHandler())
 
 
 def open(

diff --git a/rasterio/_drivers.pyx b/rasterio/_drivers.pyx
@@ -1,9 +1,9 @@
 # The GDAL and OGR driver registry.
 # GDAL driver management.
 
+import logging
 import os
 import os.path
-import logging
 import sys
 
 from rasterio.five import string_types
@@ -35,13 +35,6 @@ cdef extern from "ogr_api.h":
     int OGRGetDriverCount()
 
 
-log = logging.getLogger('GDAL')
-class NullHandler(logging.Handler):
-    def emit(self, record):
-        pass
-log.addHandler(NullHandler())
-
-
 level_map = {
     0: 0,
     1: logging.DEBUG,
@@ -50,6 +43,7 @@ level_map = {
     4: logging.CRITICAL }
 
 code_map = {
+    0: 'CPLE_None',
     1: 'CPLE_AppDefined',
     2: 'CPLE_OutOfMemory',
     3: 'CPLE_FileIO',
@@ -70,10 +64,13 @@ code_map = {
     15: 'CPLE_AWSInvalidCredentials',
     16: 'CPLE_AWSSignatureDoesNotMatch'}
 
+log = logging.getLogger('rasterio')
+
 
 cdef void * errorHandler(int eErrClass, int err_no, char *msg):
     if err_no in code_map:
-        log.log(level_map[eErrClass], "%s in %s", code_map[err_no], msg)
+        logger = logging.getLogger('GDAL')
+        logger.log(level_map[eErrClass], "%s in %s", code_map[err_no], msg)
 
 
 def driver_count():
@@ -178,7 +175,10 @@ cdef class GDALEnv(ConfigEnv):
             os.environ['PROJ_LIB'] = whl_datadir
 
     def stop(self):
-        CPLSetErrorHandler(NULL)
+        # NB: do not restore the CPL error handler to its default
+        # state here. If you do, log messages will be written to stderr
+        # by GDAL instead of being sent to Python's logging module.
+        pass
 
     def drivers(self):
         cdef void *drv = NULL

diff --git a/rasterio/rio/main.py b/rasterio/rio/main.py
@@ -16,9 +16,19 @@
 
 
 def configure_logging(verbosity):
-    log_level = max(10, 30 - 10*verbosity)
+    log_level = max(10, 30 - 10 * verbosity)
     logging.basicConfig(stream=sys.stderr, level=log_level)
 
+    # Rasterio has attached the 'rasterio' and 'GDAL' loggers to
+    # NullHandler. The CLI attaches a new StreamHandler to each
+    # so log messages go to sys.stderr.
+    log = logging.getLogger('rasterio')
+    log.setLevel(log_level)
+    log.addHandler(logging.StreamHandler())
+    log = logging.getLogger('GDAL')
+    log.setLevel(log_level)
+    log.addHandler(logging.StreamHandler())
+
 
 class FakeSession(object):
     """Fake AWS Session."""

diff --git a/tests/test_driver_management.py b/tests/test_driver_management.py
@@ -4,43 +4,44 @@
 import rasterio
 from rasterio._drivers import driver_count, GDALEnv
 
-logging.basicConfig(stream=sys.stderr, level=logging.DEBUG)
 
 def test_drivers():
     with rasterio.drivers() as m:
         assert driver_count() > 0
         assert type(m) == GDALEnv
-
         n = rasterio.drivers()
         assert driver_count() > 0
         assert type(n) == GDALEnv
 
-def test_options(tmpdir):
-    """Test that setting CPL_DEBUG=True results in GDAL debug messages.
-    """
-    logger = logging.getLogger('GDAL')
-    logger.setLevel(logging.DEBUG)
-    logfile1 = str(tmpdir.join('test_options1.log'))
-    fh = logging.FileHandler(logfile1)
-    logger.addHandler(fh)
-
-    # With CPL_DEBUG=True, expect debug messages from GDAL in
-    # logfile1
+
+def test_cpl_debug_true(tmpdir):
+    """Setting CPL_DEBUG=True results in GDAL debug messages."""
+    log = logging.getLogger('GDAL')
+    log.setLevel(logging.DEBUG)
+    logfile = str(tmpdir.join('test.log'))
+    fh = logging.FileHandler(logfile)
+    log.addHandler(fh)
+
     with rasterio.drivers(CPL_DEBUG=True):
-        with rasterio.open("tests/data/RGB.byte.tif") as src:
+        with rasterio.open("tests/data/RGB.byte.tif"):
+            pass
+
+    log = open(logfile).read()
+    assert "GDAL: GDALOpen(tests/data/RGB.byte.tif" in log
+
+
+def test_cpl_debug_false(tmpdir):
+    """Setting CPL_DEBUG=False results in no GDAL debug messages."""
+    log = logging.getLogger('GDAL')
+    log.setLevel(logging.DEBUG)
+    logfile = str(tmpdir.join('test.log'))
+    fh = logging.FileHandler(logfile)
+    log.addHandler(fh)
+
+    with rasterio.drivers(CPL_DEBUG=False):
+        with rasterio.open("tests/data/RGB.byte.tif"):
             pass
 
-    log = open(logfile1).read()
-    assert "Option CPL_DEBUG=True" in log
-
-    # The GDAL env above having exited, CPL_DEBUG should be OFF.
-    logfile2 = str(tmpdir.join('test_options2.log'))
-    fh = logging.FileHandler(logfile2)
-    logger.addHandler(fh)
-
-    with rasterio.open("tests/data/RGB.byte.tif") as src:
-        pass
-
     # Expect no debug messages from GDAL.
-    log = open(logfile2).read()
+    log = open(logfile).read()
     assert "GDAL: GDALOpen(tests/data/RGB.byte.tif" not in log