use hardcoded logging names instead of __name__ (#212)

`__name__` is only the module name, so in e.g.
`elasticapm.intrumentation.packages.base`, the logger name would be `base`.

By prefixing all logger names with `elasticapm`, it should be easier to
filter/debug log messages from elasticapm itself.

Additionally, this PR also contains tests for some of our logging.

closes #212

Author: beniwohli

CHANGELOG.asciidoc

@@ -12,6 +12,7 @@
 === Unreleased
 https://github.com/elastic/apm-agent-python/compare/v2.1.1\...master[Check the HEAD diff]
 
+ * introduced consistent logger name scheme for all elasticapm internal log messages ({pull}212[#212])
  * added instrumentation of elasticsearch-py ({pull}191[#191])
  * added Flask 1.0 to the test matrix ({pull}207[#207])
  * fixed an issue with our minimalistic SQL parser and "fully qualified" table names ({pull}206[#206])

elasticapm/contrib/django/handlers.py

@@ -20,7 +20,7 @@
 
 from elasticapm.handlers.logging import LoggingHandler as BaseLoggingHandler
 
-logger = logging.getLogger(__name__)
+logger = logging.getLogger('elasticapm.logging')
 
 
 class LoggingHandler(BaseLoggingHandler):

elasticapm/events.py

@@ -20,7 +20,7 @@
 
 __all__ = ('BaseEvent', 'Exception', 'Message')
 
-logger = logging.getLogger(__name__)
+logger = logging.getLogger('elasticapm.events')
 
 
 class BaseEvent(object):

elasticapm/instrumentation/packages/base.py

@@ -5,7 +5,7 @@
 from elasticapm.traces import get_transaction
 from elasticapm.utils import wrapt
 
-logger = logging.getLogger(__name__)
+logger = logging.getLogger('elasticapm.instrument')
 
 
 class AbstractInstrumentedModule(object):
@@ -49,12 +49,12 @@ def instrument(self):
 
         skip_env_var = 'SKIP_INSTRUMENT_' + str(self.name.upper())
         if skip_env_var in os.environ:
-            logger.debug("Skipping instrumentation of %s. %s is set.",
-                         self.name, skip_env_var)
+            logger.debug("Skipping instrumentation of %s. %s is set.", self.name, skip_env_var)
             return
         try:
             instrument_list = self.get_instrument_list()
             skipped_modules = set()
+            instrumented_methods = []
 
             for module, method in instrument_list:
                 try:
@@ -70,32 +70,35 @@ def instrument(self):
                         functools.partial(self.call_if_sampling, module, method),
                     )
                     wrapt.apply_patch(parent, attribute, wrapper)
+                    instrumented_methods.append((module, method))
                 except ImportError:
                     # Could not import module
-                    logger.debug("Skipping instrumentation of %s."
-                                 " Module %s not found",
-                                 self.name, module)
+                    logger.debug("Skipping instrumentation of %s. Module %s not found", self.name, module)
 
                     # Keep track of modules we couldn't load so we don't
                     # try to instrument anything in that module again
                     skipped_modules.add(module)
                 except AttributeError as ex:
                     # Could not find thing in module
-                    logger.debug("Skipping instrumentation of %s.%s: %s",
-                                 module, method, ex)
+                    logger.debug("Skipping instrumentation of %s.%s: %s", module, method, ex)
+            if instrumented_methods:
+                logger.debug("Instrumented %s, %s", self.name, ', '.join('.'.join(m) for m in instrumented_methods))
 
         except ImportError as ex:
-            logger.debug("Skipping instrumentation of %s. %s",
-                         self.name, ex)
+            logger.debug("Skipping instrumentation of %s. %s", self.name, ex)
         self.instrumented = True
 
     def uninstrument(self):
         if not self.instrumented or not self.originals:
             return
+        uninstrumented_methods = []
         for module, method in self.get_instrument_list():
             if (module, method) in self.originals:
                 parent, attribute, wrapper = wrapt.resolve_path(module, method)
                 wrapt.apply_patch(parent, attribute, self.originals[(module, method)])
+                uninstrumented_methods.append((module, method))
+        if uninstrumented_methods:
+            logger.debug("Uninstrumented %s, %s", self.name, ', '.join('.'.join(m) for m in uninstrumented_methods))
         self.instrumented = False
         self.originals = {}
 

elasticapm/transport/http.py

@@ -12,7 +12,7 @@
                                             HTTPTransportBase)
 from elasticapm.utils import compat
 
-logger = logging.getLogger(__name__)
+logger = logging.getLogger('elasticapm.transport.http')
 
 
 class Transport(HTTPTransportBase):

tests/instrumentation/base_tests.py

@@ -25,7 +25,7 @@ class _TestInstrumentNonExistingFunctionOnModule(AbstractInstrumentedModule):
 class _TestInstrumentNonExistingMethod(AbstractInstrumentedModule):
     name = "test_non_existing_method_instrumentation"
     instrument_list = [
-        ("dict", "non_existing_method"),
+        ("logging", "Logger.non_existing_method"),
     ]
 
 
@@ -47,36 +47,54 @@ def test_instrument_nonexisting_method_on_module():
     _TestInstrumentNonExistingFunctionOnModule().instrument()
 
 
-def test_instrument_nonexisting_method():
-    _TestInstrumentNonExistingMethod().instrument()
+def test_instrument_nonexisting_method(caplog):
+    with caplog.at_level(logging.DEBUG, 'elasticapm.instrument'):
+        _TestInstrumentNonExistingMethod().instrument()
+    record = caplog.records[0]
+    assert 'has no attribute' in record.message
 
 
 @pytest.mark.skipif(compat.PY3, reason="different object model")
-def test_uninstrument_py2():
+def test_uninstrument_py2(caplog):
     assert isinstance(Dummy.dummy, types.MethodType)
     assert not isinstance(Dummy.dummy, wrapt.BoundFunctionWrapper)
 
     instrumentation = _TestDummyInstrumentation()
-    instrumentation.instrument()
+    with caplog.at_level(logging.DEBUG, 'elasticapm.instrument'):
+        instrumentation.instrument()
+    record = caplog.records[0]
+    assert "Instrumented" in record.message
+    assert record.args == ('test_dummy_instrument', 'tests.instrumentation.base_tests.Dummy.dummy')
     assert isinstance(Dummy.dummy, wrapt.BoundFunctionWrapper)
 
-    instrumentation.uninstrument()
+    with caplog.at_level(logging.DEBUG, 'elasticapm.instrument'):
+        instrumentation.uninstrument()
+    record = caplog.records[1]
+    assert "Uninstrumented" in record.message
+    assert record.args == ('test_dummy_instrument', 'tests.instrumentation.base_tests.Dummy.dummy')
     assert isinstance(Dummy.dummy, types.MethodType)
     assert not isinstance(Dummy.dummy, wrapt.BoundFunctionWrapper)
 
 
 @pytest.mark.skipif(compat.PY2, reason="different object model")
-def test_uninstrument_py3():
+def test_uninstrument_py3(caplog):
     original = Dummy.dummy
     assert not isinstance(Dummy.dummy, wrapt.BoundFunctionWrapper)
 
     instrumentation = _TestDummyInstrumentation()
-    instrumentation.instrument()
-
+    with caplog.at_level(logging.DEBUG, 'elasticapm.instrument'):
+        instrumentation.instrument()
+    record = caplog.records[0]
+    assert "Instrumented" in record.message
+    assert record.args == ('test_dummy_instrument', 'tests.instrumentation.base_tests.Dummy.dummy')
     assert Dummy.dummy is not original
     assert isinstance(Dummy.dummy, wrapt.BoundFunctionWrapper)
 
-    instrumentation.uninstrument()
+    with caplog.at_level(logging.DEBUG, 'elasticapm.instrument'):
+        instrumentation.uninstrument()
+    record = caplog.records[1]
+    assert "Uninstrumented" in record.message
+    assert record.args == ('test_dummy_instrument', 'tests.instrumentation.base_tests.Dummy.dummy')
     assert Dummy.dummy is original
     assert not isinstance(Dummy.dummy, wrapt.BoundFunctionWrapper)
 
@@ -97,10 +115,13 @@ def test_module_method_args(elasticapm_client):
     assert call_args == ('tests.instrumentation.base_tests', 'Dummy.dummy')
 
 
-def test_skip_instrument_env_var():
+def test_skip_instrument_env_var(caplog):
     instrumentation = _TestDummyInstrumentation()
-    with mock.patch.dict('os.environ', {'SKIP_INSTRUMENT_TEST_DUMMY_INSTRUMENT': 'foo'}):
+    with mock.patch.dict('os.environ', {'SKIP_INSTRUMENT_TEST_DUMMY_INSTRUMENT': 'foo'}),\
+            caplog.at_level(logging.DEBUG, 'elasticapm.instrument'):
         instrumentation.instrument()
+    record = caplog.records[0]
+    assert 'Skipping' in record.message
     assert not instrumentation.instrumented