ENH: Added support for debugging internal PROJ (#696)

Author: snowman2

.travis.yml

@@ -30,6 +30,7 @@ matrix:
     - python: 3.6
       env:
         - PROJ_NETWORK=ON
+        - PROJ_DEBUG=3
     - python: 3.6
       env:
         - PROJSYNC=ALL

docs/advanced_examples.rst

@@ -180,3 +180,42 @@ Here is an example where enabling the global context can help:
 
     codes = pyproj.get_codes("EPSG", pyproj.enums.PJType.PROJECTED_CRS, False)
     crs_list = [pyproj.CRS.from_epsg(code) for code in codes]
+
+
+Debugging Internal PROJ:
+------------------------
+
+.. versionadded:: 3.0.0
+
+To get more debugging information from the internal PROJ code:
+
+1. Set the `PROJ_DEBUG <https://proj.org/usage/environmentvars.html#envvar-PROJ_DEBUG>`__
+   environment variable to the desired level.
+
+2. Activate logging in `pyproj` with the devel `DEBUG`:
+
+    More information available here: https://docs.python.org/3/howto/logging.html
+
+    Here are examples to get started.
+
+    Add handler to the `pyproj` logger:
+
+    .. code-block:: python
+
+        import logging
+
+        console_handler = logging.StreamHandler()
+        formatter = logging.Formatter("%(levelname)s:%(message)s")
+        console_handler.setFormatter(formatter)
+        logger = logging.getLogger("pyproj")
+        logger.addHandler(console_handler)
+        logger.setLevel(logging.DEBUG)
+
+
+    Activate default logging config:
+
+    .. code-block:: python
+
+        import logging
+
+        logging.basicConfig(format="%(levelname)s:%(message)s", level=logging.DEBUG)

docs/history.rst

@@ -23,6 +23,7 @@ Change Log
 * ENH: Add support for temporal CRS CF coordinate system (issue #672)
 * BUG: Fix handling of polygon holes when calculating area in Geod (pull #686)
 * ENH: Added :ref:`network` (#675, #691, #695)
+* ENH: Added support for debugging internal PROJ (pull #696)
 
 2.6.1
 ~~~~~

pyproj/_datadir.pyx

@@ -1,3 +1,4 @@
+import logging
 import os
 import warnings
 from distutils.util import strtobool
@@ -7,6 +8,10 @@ from libc.stdlib cimport free, malloc
 from pyproj.compat import cstrencode, pystrdecode
 from pyproj.exceptions import DataDirError, ProjError
 
+# for logging the internal PROJ messages
+# https://docs.python.org/3/howto/logging.html#configuring-logging-for-a-library
+_LOGGER = logging.getLogger("pyproj")
+_LOGGER.addHandler(logging.NullHandler())
 # default to False is the safest mode
 # as it supports multithreading
 _USE_GLOBAL_CONTEXT = strtobool(os.environ.get("PYPROJ_GLOBAL_CONTEXT", "OFF"))
@@ -70,12 +75,23 @@ def get_user_data_dir(create=False):
     return pystrdecode(proj_context_get_user_writable_directory(NULL, bool(create)))
 
 
-cdef void pyproj_log_function(void *user_data, int level, const char *error_msg):
+cdef void pyproj_log_function(void *user_data, int level, const char *error_msg) nogil:
     """
     Log function for catching PROJ errors.
     """
+    # from pyproj perspective, everything from PROJ is for debugging.
+    # The verbosity should be managed via the
+    # PROJ_DEBUG environment variable.
     if level == PJ_LOG_ERROR:
-        ProjError.internal_proj_error = pystrdecode(error_msg)
+        with gil:
+            ProjError.internal_proj_error = pystrdecode(error_msg)
+            _LOGGER.debug(f"PROJ_ERROR: {ProjError.internal_proj_error}")
+    elif level == PJ_LOG_DEBUG:
+        with gil:
+            _LOGGER.debug(f"PROJ_DEBUG: {pystrdecode(error_msg)}")
+    elif level == PJ_LOG_TRACE:
+        with gil:
+            _LOGGER.debug(f"PROJ_TRACE: {pystrdecode(error_msg)}")
 
 
 cdef void set_context_data_dir(PJ_CONTEXT* context) except *:

test/test_datadir.py

@@ -1,11 +1,12 @@
+import logging
 import os
 from contextlib import contextmanager
 
 import pytest
 from mock import patch
 
 import pyproj._datadir
-from pyproj import CRS, get_codes, set_use_global_context
+from pyproj import CRS, Transformer, get_codes, set_use_global_context
 from pyproj._datadir import _pyproj_global_context_initialize
 from pyproj.datadir import (
     DataDirError,
@@ -15,6 +16,7 @@
     set_data_dir,
 )
 from pyproj.enums import PJType
+from pyproj.exceptions import CRSError
 from test.conftest import proj_env
 
 
@@ -30,6 +32,23 @@ def proj_context_env():
         pyproj._datadir._USE_GLOBAL_CONTEXT = context
 
 
+@contextmanager
+def proj_logging_env():
+    """
+    Ensure handler is added and then removed at end.
+    """
+    console_handler = logging.StreamHandler()
+    formatter = logging.Formatter("%(threadName)s:%(levelname)s:%(message)s")
+    console_handler.setFormatter(formatter)
+    logger = logging.getLogger("pyproj")
+    logger.addHandler(console_handler)
+    logger.setLevel(logging.DEBUG)
+    try:
+        yield
+    finally:
+        logger.removeHandler(console_handler)
+
+
 def create_projdb(tmpdir):
     with open(os.path.join(tmpdir, "proj.db"), "w") as pjdb:
         pjdb.write("DUMMY proj.db")
@@ -227,3 +246,36 @@ def test_set_use_global_context__off():
     with proj_context_env():
         set_use_global_context(False)
         assert pyproj._datadir._USE_GLOBAL_CONTEXT is False
+
+
+def test_proj_debug_logging(capsys):
+    with proj_logging_env():
+        with pytest.warns(FutureWarning):
+            transformer = Transformer.from_proj("+init=epsg:4326", "+init=epsg:27700")
+        transformer.transform(100000, 100000)
+        captured = capsys.readouterr()
+        if os.environ.get("PROJ_DEBUG") == "3":
+            assert "PROJ_TRACE" in captured.err
+            assert "PROJ_DEBUG" in captured.err
+        elif os.environ.get("PROJ_DEBUG") == "2":
+            assert "PROJ_TRACE" not in captured.err
+            assert "PROJ_DEBUG" in captured.err
+        else:
+            assert captured.err == ""
+
+
+def test_proj_debug_logging__error(capsys):
+    with proj_logging_env(), pytest.raises(CRSError):
+        CRS("INVALID STRING")
+        captured = capsys.readouterr()
+        if os.environ.get("PROJ_DEBUG") == "3":
+            assert "PROJ_TRACE" in captured.err
+            assert "PROJ_DEBUG" in captured.err
+            assert "PROJ_ERROR" in captured.err
+        elif os.environ.get("PROJ_DEBUG") == "2":
+            assert "PROJ_TRACE" not in captured.err
+            assert "PROJ_DEBUG" in captured.err
+            assert "PROJ_ERROR" in captured.err
+        else:
+            assert captured.err == ""
+            assert captured.out == ""