Merge pull request #790 from DataDog/0.20-dev

Merge 0.20-dev

.circleci/config.yml

@@ -190,6 +190,20 @@ jobs:
             - test_utils.results
       - *save_cache_step
 
+  test_logging:
+    docker:
+      - *test_runner
+    resource_class: *resource_class
+    steps:
+      - checkout
+      - *restore_cache_step
+      - run: tox -e '{py27,py34,py35,py36}-test_logging' --result-json /tmp/test_logging.results
+      - persist_to_workspace:
+          root: /tmp
+          paths:
+            - test_logging.results
+      - *save_cache_step
+
   asyncio:
     docker:
       - *test_runner
@@ -884,6 +898,20 @@ jobs:
             - jinja2.results
       - *save_cache_step
 
+  mako:
+    docker:
+      - *test_runner
+    resource_class: *resource_class
+    steps:
+      - checkout
+      - *restore_cache_step
+      - run: tox -e 'mako_contrib-{py27,py34,py35,py36}-mako{010,100}' --result-json /tmp/mako.results
+      - persist_to_workspace:
+          root: /tmp
+          paths:
+            - mako.results
+      - *save_cache_step
+
   build_docs:
     # deploy official documentation
     docker:
@@ -1018,6 +1046,9 @@ workflows:
       - kombu:
           requires:
             - flake8
+      - mako:
+          requires:
+            - flake8
       - molten:
           requires:
             - flake8
@@ -1081,6 +1112,9 @@ workflows:
       - test_utils:
           requires:
             - flake8
+      - test_logging:
+          requires:
+            - flake8
       - tornado:
           requires:
             - flake8
@@ -1122,6 +1156,7 @@ workflows:
             - integration
             - jinja2
             - kombu
+            - mako
             - molten
             - mongoengine
             - msgpack
@@ -1143,6 +1178,7 @@ workflows:
             - sqlalchemy
             - sqlite3
             - test_utils
+            - test_logging
             - tornado
             - tracer
             - unit_tests

ddtrace/__init__.py

@@ -4,7 +4,7 @@
 from .tracer import Tracer
 from .settings import config
 
-__version__ = '0.19.0'
+__version__ = '0.20.0'
 
 # a global tracer instance with integration settings
 tracer = Tracer()

ddtrace/bootstrap/sitecustomize.py

@@ -8,14 +8,25 @@
 import sys
 import logging
 
-from ddtrace.utils.formats import asbool
+from ddtrace.utils.formats import asbool, get_env
 
+logs_injection = asbool(get_env('logs', 'injection'))
+DD_LOG_FORMAT = '%(asctime)s %(levelname)s [%(name)s] [%(filename)s:%(lineno)d] {}- %(message)s'.format(
+    '[dd.trace_id=%(dd.trace_id)s dd.span_id=%(dd.span_id)s] ' if logs_injection else ''
+)
 
 debug = os.environ.get("DATADOG_TRACE_DEBUG")
+
+# Set here a default logging format for basicConfig
+
+# DEV: Once basicConfig is called here, future calls to it cannot be used to
+# change the formatter since it applies the formatter to the root handler only
+# upon initializing it the first time.
+# See https://github.com/python/cpython/blob/112e4afd582515fcdcc0cde5012a4866e5cfda12/Lib/logging/__init__.py#L1550
 if debug and debug.lower() == "true":
-    logging.basicConfig(level=logging.DEBUG)
+    logging.basicConfig(level=logging.DEBUG, format=DD_LOG_FORMAT)
 else:
-    logging.basicConfig()
+    logging.basicConfig(format=DD_LOG_FORMAT)
 
 log = logging.getLogger(__name__)
 
@@ -82,6 +93,9 @@ def add_global_tags(tracer):
     if opts:
         tracer.configure(**opts)
 
+    if logs_injection:
+        EXTRA_PATCHED_MODULES.update({'logging': True})
+
     if patch:
         update_patched_modules()
         from ddtrace import patch_all; patch_all(**EXTRA_PATCHED_MODULES) # noqa

ddtrace/contrib/logging/__init__.py

@@ -0,0 +1,66 @@
+"""
+Datadog APM traces can be integrated with Logs by first having the tracing
+library patch the standard library ``logging`` module and updating the log
+formatter used by an application. This feature enables you to inject the current
+trace information into a log entry.
+
+Before the trace information can be injected into logs, the formatter has to be
+updated to include ``dd.trace_id`` and ``dd.span_id`` attributes from the log
+record. The integration with Logs occurs as long as the log entry includes
+``dd.trace_id=%(dd.trace_id)s`` and ``dd.span_id=%(dd.span_id)s``.
+
+ddtrace-run
+-----------
+
+When using ``ddtrace-run``, enable patching by setting the environment variable
+``DD_LOGS_INJECTION=true``. The logger by default will have a format that
+includes trace information::
+
+    import logging
+    from ddtrace import tracer
+
+    log = logging.getLogger()
+    log.level = logging.INFO
+
+
+    @tracer.wrap()
+    def hello():
+        log.info('Hello, World!')
+
+    hello()
+
+Manual Instrumentation
+----------------------
+
+If you prefer to instrument manually, patch the logging library then update the
+log formatter as in the following example::
+
+    from ddtrace import patch_all; patch_all(logging=True)
+    import logging
+    from ddtrace import tracer
+
+    FORMAT = ('%(asctime)s %(levelname)s [%(name)s] [%(filename)s:%(lineno)d] '
+              '[dd.trace_id=%(dd.trace_id)s dd.span_id=%(dd.span_id)s] '
+              '- %(message)s')
+    logging.basicConfig(format=FORMAT)
+    log = logging.getLogger()
+    log.level = logging.INFO
+
+
+    @tracer.wrap()
+    def hello():
+        log.info('Hello, World!')
+
+    hello()
+"""
+
+from ...utils.importlib import require_modules
+
+
+required_modules = ['logging']
+
+with require_modules(required_modules) as missing_modules:
+    if not missing_modules:
+        from .patch import patch, unpatch
+
+        __all__ = ['patch', 'unpatch']

ddtrace/contrib/logging/patch.py

@@ -0,0 +1,49 @@
+import logging
+from wrapt import wrap_function_wrapper as _w
+
+from ddtrace import config
+
+from ...helpers import get_correlation_ids
+from ...utils.wrappers import unwrap as _u
+
+RECORD_ATTR_TRACE_ID = 'dd.trace_id'
+RECORD_ATTR_SPAN_ID = 'dd.span_id'
+RECORD_ATTR_VALUE_NULL = 0
+
+config._add('logging', dict(
+    tracer=None,  # by default, override here for custom tracer
+))
+
+
+def _w_makeRecord(func, instance, args, kwargs):
+    record = func(*args, **kwargs)
+
+    # add correlation identifiers to LogRecord
+    trace_id, span_id = get_correlation_ids(tracer=config.logging.tracer)
+    if trace_id and span_id:
+        setattr(record, RECORD_ATTR_TRACE_ID, trace_id)
+        setattr(record, RECORD_ATTR_SPAN_ID, span_id)
+    else:
+        setattr(record, RECORD_ATTR_TRACE_ID, RECORD_ATTR_VALUE_NULL)
+        setattr(record, RECORD_ATTR_SPAN_ID, RECORD_ATTR_VALUE_NULL)
+
+    return record
+
+
+def patch():
+    """
+    Patch ``logging`` module in the Python Standard Library for injection of
+    tracer information by wrapping the base factory method ``Logger.makeRecord``
+    """
+    if getattr(logging, '_datadog_patch', False):
+        return
+    setattr(logging, '_datadog_patch', True)
+
+    _w(logging.Logger, 'makeRecord', _w_makeRecord)
+
+
+def unpatch():
+    if getattr(logging, '_datadog_patch', False):
+        setattr(logging, '_datadog_patch', False)
+
+        _u(logging.Logger, 'makeRecord')

ddtrace/contrib/mako/__init__.py

@@ -0,0 +1,24 @@
+"""
+The ``mako`` integration traces templates rendering.
+Auto instrumentation is available using the ``patch``. The following is an example::
+
+    from ddtrace import patch
+    from mako.template import Template
+
+    patch(mako=True)
+
+    t = Template(filename="index.html")
+
+"""
+from ..util import require_modules
+
+required_modules = ['mako']
+
+with require_modules(required_modules) as missing_modules:
+    if not missing_modules:
+        from .patch import patch, unpatch
+
+        __all__ = [
+            'patch',
+            'unpatch',
+        ]

ddtrace/contrib/mako/constants.py

@@ -0,0 +1 @@
+DEFAULT_TEMPLATE_NAME = '<memory>'

ddtrace/contrib/mako/patch.py

@@ -0,0 +1,47 @@
+import mako
+from mako.template import Template
+from wrapt import wrap_function_wrapper as _w
+
+from ...ext import http
+from ...pin import Pin
+from ...utils.importlib import func_name
+from ...utils.wrappers import unwrap as _u
+from .constants import DEFAULT_TEMPLATE_NAME
+
+
+def patch():
+    if getattr(mako, '__datadog_patch', False):
+        # already patched
+        return
+    setattr(mako, '__datadog_patch', True)
+
+    Pin(service='mako', app='mako', app_type=http.TEMPLATE).onto(Template)
+
+    _w(mako, 'template.Template.render', _wrap_render)
+    _w(mako, 'template.Template.render_unicode', _wrap_render)
+    _w(mako, 'template.Template.render_context', _wrap_render)
+
+
+def unpatch():
+    if not getattr(mako, '__datadog_patch', False):
+        return
+    setattr(mako, '__datadog_patch', False)
+
+    _u(mako.template.Template, 'render')
+    _u(mako.template.Template, 'render_unicode')
+    _u(mako.template.Template, 'render_context')
+
+
+def _wrap_render(wrapped, instance, args, kwargs):
+    pin = Pin.get_from(instance)
+    if not pin or not pin.enabled():
+        return wrapped(*args, **kwargs)
+
+    template_name = instance.filename or DEFAULT_TEMPLATE_NAME
+    with pin.tracer.trace(func_name(wrapped), pin.service, span_type=http.TEMPLATE) as span:
+        try:
+            template = wrapped(*args, **kwargs)
+            return template
+        finally:
+            span.resource = template_name
+            span.set_tag('mako.template_name', template_name)

ddtrace/helpers.py

@@ -1,7 +1,7 @@
 import ddtrace
 
 
-def get_correlation_ids():
+def get_correlation_ids(tracer=None):
     """Retrieves the Correlation Identifiers for the current active ``Trace``.
     This helper method can be achieved manually and should be considered
     only a shortcut. The main reason is to abstract the current ``Tracer``
@@ -11,9 +11,9 @@ def get_correlation_ids():
     OpenTracing users can still extract these values using the ``ScopeManager``
     API, though this shortcut is a simple one-liner. The usage is:
 
-        from ddtrace import correlation
+        from ddtrace import helpers
 
-        trace_id, span_id = correlation.get_correlation_ids()
+        trace_id, span_id = helpers.get_correlation_ids()
 
     :returns: a tuple containing the trace_id and span_id
     """
@@ -22,7 +22,15 @@ def get_correlation_ids():
     # and we're doing the same here for ``ddtrace.tracer``. Because this helper
     # must work also with OpenTracing, we should take the right used ``Tracer``.
     # At the time of writing, it's enough to support our Datadog Tracer.
-    tracer = ddtrace.tracer
+
+    # If no tracer passed in, use global tracer
+    if not tracer:
+        tracer = ddtrace.tracer
+
+    # If tracer is disabled, skip
+    if not tracer.enabled:
+        return None, None
+
     span = tracer.current_span()
     if span is None:
         return None, None

ddtrace/monkey.py

@@ -46,6 +46,7 @@
     'vertica': True,
     'molten': True,
     'jinja2': True,
+    'mako': True,
     'flask': True,
     'kombu': False,
 
@@ -54,6 +55,9 @@
     "falcon": False,
     "pylons": False,
     "pyramid": False,
+
+    # Standard library modules off by default
+    'logging': False,
 }
 
 _LOCK = threading.Lock()

docs/advanced_usage.rst

@@ -238,6 +238,13 @@ next step of the pipeline or ``None`` if the trace should be discarded::
 
 (see filters.py for other example implementations)
 
+.. _`Logs Injection`:
+
+Logs Injection
+--------------
+
+.. automodule:: ddtrace.contrib.logging
+
 Http layer
 ----------
 
@@ -447,6 +454,7 @@ The available environment variables for ``ddtrace-run`` are:
   will submit to  (default: 8126)
 * ``DATADOG_PRIORITY_SAMPLING`` (default: true): enables :ref:`Priority
   Sampling`
+* ``DD_LOGS_INJECTION`` (default: false): enables :ref:`Logs Injection`
 
 ``ddtrace-run`` respects a variety of common entrypoints for web applications: