Repository: scoutapp/scout_apm_python
Pull request #502 (2020-03-09 18:42:29)

Improve log messages around instrumentation
A user was confused around the log messages stating that we failed to import elasticsearch, wondering why Scout depends on it.

This improves the log messages to be at DEBUG level only for attempts to instruments, and rewords them to be a little clearer around the process.


Patch:
diff --git a/CHANGELOG.md b/CHANGELOG.md
index 5c826a1..d757928 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -13,6 +13,8 @@
   `core_agent_` prefix. This is to clarify that they apply only to the core
   agent process. The old names continue to work as aliases.
   ([Issue #497](https://github.com/scoutapp/scout_apm_python/issues/497))
+- Improved some log messages and levels around instrumentation.
+  ([Issue #502](https://github.com/scoutapp/scout_apm_python/pull/502))
 
 ## [2.12.0] 2020-03-03
 
diff --git a/src/scout_apm/instruments/elasticsearch.py b/src/scout_apm/instruments/elasticsearch.py
index 20f21d2..32a4008 100644
--- a/src/scout_apm/instruments/elasticsearch.py
+++ b/src/scout_apm/instruments/elasticsearch.py
@@ -19,10 +19,12 @@ logger = logging.getLogger(__name__)
 
 
 def ensure_installed():
-    logger.info("Ensuring elasticsearch instrumentation is installed.")
+    logger.debug("Instrumenting elasticsearch.")
 
     if Elasticsearch is None:
-        logger.info("Unable to import elasticsearch.Elasticsearch")
+        logger.debug(
+            "Couldn't import elasticsearch.Elasticsearch - probably not installed."
+        )
     else:
         ensure_client_instrumented()
         ensure_transport_instrumented()
@@ -87,7 +89,7 @@ def ensure_client_instrumented():
                 setattr(Elasticsearch, name, wrapped)
             except Exception as exc:
                 logger.warning(
-                    "Unable to instrument elasticsearch.Elasticsearch.%s: %r",
+                    "Failed to instrument elasticsearch.Elasticsearch.%s: %r",
                     name,
                     exc,
                     exc_info=exc,
@@ -161,7 +163,7 @@ def ensure_transport_instrumented():
             )
         except Exception as exc:
             logger.warning(
-                "Unable to instrument elasticsearch.Transport.perform_request: %r",
+                "Failed to instrument elasticsearch.Transport.perform_request: %r",
                 exc,
                 exc_info=exc,
             )
diff --git a/src/scout_apm/instruments/jinja2.py b/src/scout_apm/instruments/jinja2.py
index 27119cc..08bf54a 100644
--- a/src/scout_apm/instruments/jinja2.py
+++ b/src/scout_apm/instruments/jinja2.py
@@ -37,10 +37,10 @@ def ensure_installed():
     global have_patched_environment_init
     global have_patched_template_render
 
-    logger.info("Ensuring Jinja2 instrumentation is installed.")
+    logger.debug("Instrumenting Jinja2.")
 
     if Template is None:
-        logger.info("Unable to import jinja2.Template")
+        logger.debug("Couldn't import jinja2.Template - probably not installed.")
         return
 
     if not have_patched_environment_init:
@@ -48,7 +48,7 @@ def ensure_installed():
             Environment.__init__ = wrapped_environment_init(Environment.__init__)
         except Exception as exc:
             logger.warning(
-                "Unable to instrument jinja2.Environment.__init__: %r",
+                "Failed to instrument jinja2.Environment.__init__: %r",
                 exc,
                 exc_info=exc,
             )
@@ -60,7 +60,7 @@ def ensure_installed():
             Template.render = wrapped_render(Template.render)
         except Exception as exc:
             logger.warning(
-                "Unable to instrument jinja2.Template.render: %r", exc, exc_info=exc
+                "Failed to instrument jinja2.Template.render: %r", exc, exc_info=exc
             )
         else:
             have_patched_template_render = True
@@ -97,7 +97,7 @@ def wrapped_environment_init(wrapped, instance, args, kwargs):
             Template.render_async = wrapped_render_async(Template.render_async)
         except Exception as exc:
             logger.warning(
-                "Unable to instrument jinja2.Template.render_async: %r",
+                "Failed to instrument jinja2.Template.render_async: %r",
                 exc,
                 exc_info=exc,
             )
diff --git a/src/scout_apm/instruments/pymongo.py b/src/scout_apm/instruments/pymongo.py
index 0fbe9a8..991abe1 100644
--- a/src/scout_apm/instruments/pymongo.py
+++ b/src/scout_apm/instruments/pymongo.py
@@ -20,10 +20,10 @@ have_patched_collection = False
 def ensure_installed():
     global have_patched_collection
 
-    logger.info("Ensuring pymongo instrumentation is installed.")
+    logger.debug("Instrumenting pymongo.")
 
     if Collection is None:
-        logger.info("Unable to import pymongo.Collection")
+        logger.debug("Couldn't import pymongo.Collection - probably not installed.")
     elif not have_patched_collection:
         for name in COLLECTION_METHODS:
             try:
@@ -32,7 +32,7 @@ def ensure_installed():
                 )
             except Exception as exc:
                 logger.warning(
-                    "Unable to instrument pymongo.Collection.%s: %r",
+                    "Failed to instrument pymongo.Collection.%s: %r",
                     name,
                     exc,
                     exc_info=exc,
diff --git a/src/scout_apm/instruments/redis.py b/src/scout_apm/instruments/redis.py
index 721e103..e3baf4b 100644
--- a/src/scout_apm/instruments/redis.py
+++ b/src/scout_apm/instruments/redis.py
@@ -29,17 +29,17 @@ have_patched_pipeline_execute = False
 def ensure_installed():
     global have_patched_redis_execute_command, have_patched_pipeline_execute
 
-    logger.info("Ensuring redis instrumentation is installed.")
+    logger.debug("Instrumenting redis.")
 
     if redis is None:
-        logger.info("Unable to import redis")
+        logger.debug("Couldn't import redis - probably not installed.")
     else:
         if not have_patched_redis_execute_command:
             try:
                 Redis.execute_command = wrapped_execute_command(Redis.execute_command)
             except Exception as exc:
                 logger.warning(
-                    "Unable to instrument redis.Redis.execute_command: %r",
+                    "Failed to instrument redis.Redis.execute_command: %r",
                     exc,
                     exc_info=exc,
                 )
@@ -51,7 +51,7 @@ def ensure_installed():
                 Pipeline.execute = wrapped_execute(Pipeline.execute)
             except Exception as exc:
                 logger.warning(
-                    "Unable to instrument redis.Pipeline.execute: %r", exc, exc_info=exc
+                    "Failed to instrument redis.Pipeline.execute: %r", exc, exc_info=exc
                 )
             else:
                 have_patched_pipeline_execute = True
diff --git a/src/scout_apm/instruments/urllib3.py b/src/scout_apm/instruments/urllib3.py
index 596fedf..1019041 100644
--- a/src/scout_apm/instruments/urllib3.py
+++ b/src/scout_apm/instruments/urllib3.py
@@ -21,17 +21,19 @@ have_patched_pool_urlopen = False
 def ensure_installed():
     global have_patched_pool_urlopen
 
-    logger.info("Ensuring urllib3 instrumentation is installed.")
+    logger.debug("Instrumenting urllib3.")
 
     if HTTPConnectionPool is None:
-        logger.info("Unable to import urllib3.HTTPConnectionPool")
+        logger.debug(
+            "Couldn't import urllib3.HTTPConnectionPool - probably not installed."
+        )
         return False
     elif not have_patched_pool_urlopen:
         try:
             HTTPConnectionPool.urlopen = wrapped_urlopen(HTTPConnectionPool.urlopen)
         except Exception as exc:
             logger.warning(
-                "Unable to instrument for Urllib3 HTTPConnectionPool.urlopen: %r",
+                "Failed to instrument for Urllib3 HTTPConnectionPool.urlopen: %r",
                 exc,
                 exc_info=exc,
             )


Test patch:
diff --git a/tests/integration/instruments/test_elasticsearch.py b/tests/integration/instruments/test_elasticsearch.py
index 6e2aa04..846e3c5 100644
--- a/tests/integration/instruments/test_elasticsearch.py
+++ b/tests/integration/instruments/test_elasticsearch.py
@@ -60,8 +60,8 @@ def test_ensure_installed_twice(caplog):
     assert caplog.record_tuples == 2 * [
         (
             "scout_apm.instruments.elasticsearch",
-            logging.INFO,
-            "Ensuring elasticsearch instrumentation is installed.",
+            logging.DEBUG,
+            "Instrumenting elasticsearch.",
         )
     ]
 
@@ -76,13 +76,13 @@ def test_ensure_installed_fail_no_client(caplog):
     assert caplog.record_tuples == [
         (
             "scout_apm.instruments.elasticsearch",
-            logging.INFO,
-            "Ensuring elasticsearch instrumentation is installed.",
+            logging.DEBUG,
+            "Instrumenting elasticsearch.",
         ),
         (
             "scout_apm.instruments.elasticsearch",
-            logging.INFO,
-            "Unable to import elasticsearch.Elasticsearch",
+            logging.DEBUG,
+            "Couldn't import elasticsearch.Elasticsearch - probably not installed.",
         ),
     ]
 
@@ -98,14 +98,14 @@ def test_ensure_installed_fail_no_client_bulk(caplog):
     assert len(caplog.record_tuples) == 2
     assert caplog.record_tuples[0] == (
         "scout_apm.instruments.elasticsearch",
-        logging.INFO,
-        "Ensuring elasticsearch instrumentation is installed.",
+        logging.DEBUG,
+        "Instrumenting elasticsearch.",
     )
     logger, level, message = caplog.record_tuples[1]
     assert logger == "scout_apm.instruments.elasticsearch"
     assert level == logging.WARNING
     assert message.startswith(
-        "Unable to instrument elasticsearch.Elasticsearch.bulk: AttributeError"
+        "Failed to instrument elasticsearch.Elasticsearch.bulk: AttributeError"
     )
 
 
@@ -122,14 +122,14 @@ def test_ensure_installed_fail_no_transport_perform_request(caplog):
     assert len(caplog.record_tuples) == 2
     assert caplog.record_tuples[0] == (
         "scout_apm.instruments.elasticsearch",
-        logging.INFO,
-        "Ensuring elasticsearch instrumentation is installed.",
+        logging.DEBUG,
+        "Instrumenting elasticsearch.",
     )
     logger, level, message = caplog.record_tuples[1]
     assert logger == "scout_apm.instruments.elasticsearch"
     assert level == logging.WARNING
     assert message.startswith(
-        "Unable to instrument elasticsearch.Transport.perform_request: AttributeError"
+        "Failed to instrument elasticsearch.Transport.perform_request: AttributeError"
     )
 
 
diff --git a/tests/integration/instruments/test_jinja2.py b/tests/integration/instruments/test_jinja2.py
index 386bf38..22c5b69 100644
--- a/tests/integration/instruments/test_jinja2.py
+++ b/tests/integration/instruments/test_jinja2.py
@@ -30,11 +30,7 @@ def test_ensure_installed_twice(caplog):
     ensure_installed()
 
     assert caplog.record_tuples == 2 * [
-        (
-            "scout_apm.instruments.jinja2",
-            logging.INFO,
-            "Ensuring Jinja2 instrumentation is installed.",
-        )
+        ("scout_apm.instruments.jinja2", logging.DEBUG, "Instrumenting Jinja2.",)
     ]
 
 
@@ -44,15 +40,11 @@ def test_ensure_installed_fail_no_template(caplog):
         ensure_installed()
 
     assert caplog.record_tuples == [
+        ("scout_apm.instruments.jinja2", logging.DEBUG, "Instrumenting Jinja2.",),
         (
             "scout_apm.instruments.jinja2",
-            logging.INFO,
-            "Ensuring Jinja2 instrumentation is installed.",
-        ),
-        (
-            "scout_apm.instruments.jinja2",
-            logging.INFO,
-            "Unable to import jinja2.Template",
+            logging.DEBUG,
+            "Couldn't import jinja2.Template - probably not installed.",
         ),
     ]
 
@@ -68,14 +60,14 @@ def test_ensure_installed_fail_no_render_attribute(caplog):
     assert len(caplog.record_tuples) == 2
     assert caplog.record_tuples[0] == (
         "scout_apm.instruments.jinja2",
-        logging.INFO,
-        "Ensuring Jinja2 instrumentation is installed.",
+        logging.DEBUG,
+        "Instrumenting Jinja2.",
     )
     logger, level, message = caplog.record_tuples[1]
     assert logger == "scout_apm.instruments.jinja2"
     assert level == logging.WARNING
     assert message.startswith(
-        "Unable to instrument jinja2.Template.render: AttributeError"
+        "Failed to instrument jinja2.Template.render: AttributeError"
     )
 
 
diff --git a/tests/integration/instruments/test_jinja2_py36plus.py b/tests/integration/instruments/test_jinja2_py36plus.py
index af520ab..7d2eaaa 100644
--- a/tests/integration/instruments/test_jinja2_py36plus.py
+++ b/tests/integration/instruments/test_jinja2_py36plus.py
@@ -21,11 +21,7 @@ def test_ensure_installed_fail_no_render_async_attribute(caplog):
         jinja2.Environment()
 
     assert caplog.record_tuples == [
-        (
-            "scout_apm.instruments.jinja2",
-            logging.INFO,
-            "Ensuring Jinja2 instrumentation is installed.",
-        )
+        ("scout_apm.instruments.jinja2", logging.DEBUG, "Instrumenting Jinja2.",)
     ]
 
 
diff --git a/tests/integration/instruments/test_pymongo.py b/tests/integration/instruments/test_pymongo.py
index 2b44801..b7d6e57 100644
--- a/tests/integration/instruments/test_pymongo.py
+++ b/tests/integration/instruments/test_pymongo.py
@@ -58,11 +58,7 @@ def test_ensure_installed_twice(caplog):
     ensure_installed()
 
     assert caplog.record_tuples == 2 * [
-        (
-            "scout_apm.instruments.pymongo",
-            logging.INFO,
-            "Ensuring pymongo instrumentation is installed.",
-        )
+        ("scout_apm.instruments.pymongo", logging.DEBUG, "Instrumenting pymongo.",)
     ]
 
 
@@ -74,15 +70,11 @@ def test_ensure_installed_fail_no_collection(caplog):
         ensure_installed()
 
     assert caplog.record_tuples == [
+        ("scout_apm.instruments.pymongo", logging.DEBUG, "Instrumenting pymongo.",),
         (
             "scout_apm.instruments.pymongo",
-            logging.INFO,
-            "Ensuring pymongo instrumentation is installed.",
-        ),
-        (
-            "scout_apm.instruments.pymongo",
-            logging.INFO,
-            "Unable to import pymongo.Collection",
+            logging.DEBUG,
+            "Couldn't import pymongo.Collection - probably not installed.",
         ),
     ]
 
@@ -100,14 +92,14 @@ def test_ensure_installed_fail_no_collection_aggregate(caplog):
     assert len(caplog.record_tuples) == 2
     assert caplog.record_tuples[0] == (
         "scout_apm.instruments.pymongo",
-        logging.INFO,
-        "Ensuring pymongo instrumentation is installed.",
+        logging.DEBUG,
+        "Instrumenting pymongo.",
     )
     logger, level, message = caplog.record_tuples[1]
     assert logger == "scout_apm.instruments.pymongo"
     assert level == logging.WARNING
     assert message.startswith(
-        "Unable to instrument pymongo.Collection.aggregate: AttributeError"
+        "Failed to instrument pymongo.Collection.aggregate: AttributeError"
     )
 
 
diff --git a/tests/integration/instruments/test_redis.py b/tests/integration/instruments/test_redis.py
index e17cb38..30cdc9c 100644
--- a/tests/integration/instruments/test_redis.py
+++ b/tests/integration/instruments/test_redis.py
@@ -25,11 +25,7 @@ def test_ensure_installed_twice(caplog):
     ensure_installed()
 
     assert caplog.record_tuples == 2 * [
-        (
-            "scout_apm.instruments.redis",
-            logging.INFO,
-            "Ensuring redis instrumentation is installed.",
-        )
+        ("scout_apm.instruments.redis", logging.DEBUG, "Instrumenting redis.",)
     ]
 
 
@@ -39,12 +35,12 @@ def test_install_fail_no_redis(caplog):
         ensure_installed()
 
     assert caplog.record_tuples == [
+        ("scout_apm.instruments.redis", logging.DEBUG, "Instrumenting redis.",),
         (
             "scout_apm.instruments.redis",
-            logging.INFO,
-            "Ensuring redis instrumentation is installed.",
+            logging.DEBUG,
+            "Couldn't import redis - probably not installed.",
         ),
-        ("scout_apm.instruments.redis", logging.INFO, "Unable to import redis"),
     ]
 
 
@@ -61,14 +57,14 @@ def test_ensure_installed_fail_no_redis_execute_command(caplog):
     assert len(caplog.record_tuples) == 2
     assert caplog.record_tuples[0] == (
         "scout_apm.instruments.redis",
-        logging.INFO,
-        "Ensuring redis instrumentation is installed.",
+        logging.DEBUG,
+        "Instrumenting redis.",
     )
     logger, level, message = caplog.record_tuples[1]
     assert logger == "scout_apm.instruments.redis"
     assert level == logging.WARNING
     assert message.startswith(
-        "Unable to instrument redis.Redis.execute_command: AttributeError"
+        "Failed to instrument redis.Redis.execute_command: AttributeError"
     )
 
 
@@ -85,14 +81,14 @@ def test_ensure_installed_fail_no_pipeline_execute(caplog):
     assert len(caplog.record_tuples) == 2
     assert caplog.record_tuples[0] == (
         "scout_apm.instruments.redis",
-        logging.INFO,
-        "Ensuring redis instrumentation is installed.",
+        logging.DEBUG,
+        "Instrumenting redis.",
     )
     logger, level, message = caplog.record_tuples[1]
     assert logger == "scout_apm.instruments.redis"
     assert level == logging.WARNING
     assert message.startswith(
-        "Unable to instrument redis.Pipeline.execute: AttributeError"
+        "Failed to instrument redis.Pipeline.execute: AttributeError"
     )
 
 
diff --git a/tests/integration/instruments/test_urllib3.py b/tests/integration/instruments/test_urllib3.py
index 8e76582..6d8cc06 100644
--- a/tests/integration/instruments/test_urllib3.py
+++ b/tests/integration/instruments/test_urllib3.py
@@ -22,11 +22,7 @@ def test_ensure_installed_twice(caplog):
     ensure_installed()
 
     assert caplog.record_tuples == 2 * [
-        (
-            "scout_apm.instruments.urllib3",
-            logging.INFO,
-            "Ensuring urllib3 instrumentation is installed.",
-        )
+        ("scout_apm.instruments.urllib3", logging.DEBUG, "Instrumenting urllib3.",)
     ]
 
 
@@ -38,15 +34,11 @@ def test_install_fail_no_httpconnectionpool(caplog):
         ensure_installed()
 
     assert caplog.record_tuples == [
+        ("scout_apm.instruments.urllib3", logging.DEBUG, "Instrumenting urllib3.",),
         (
             "scout_apm.instruments.urllib3",
-            logging.INFO,
-            "Ensuring urllib3 instrumentation is installed.",
-        ),
-        (
-            "scout_apm.instruments.urllib3",
-            logging.INFO,
-            "Unable to import urllib3.HTTPConnectionPool",
+            logging.DEBUG,
+            "Couldn't import urllib3.HTTPConnectionPool - probably not installed.",
         ),
     ]
 
@@ -62,14 +54,14 @@ def test_install_fail_no_urlopen_attribute(caplog):
     assert len(caplog.record_tuples) == 2
     assert caplog.record_tuples[0] == (
         "scout_apm.instruments.urllib3",
-        logging.INFO,
-        "Ensuring urllib3 instrumentation is installed.",
+        logging.DEBUG,
+        "Instrumenting urllib3.",
     )
     logger, level, message = caplog.record_tuples[1]
     assert logger == "scout_apm.instruments.urllib3"
     assert level == logging.WARNING
     assert message.startswith(
-        "Unable to instrument for Urllib3 HTTPConnectionPool.urlopen: AttributeError"
+        "Failed to instrument for Urllib3 HTTPConnectionPool.urlopen: AttributeError"
     )