Add logging integrations with logging and structlog (#586)

* Add logging integrations with logging and structlog

* Update changelog

* Simplify and make naming consistent

* Add span.id to logging (and pub API) as well

* Fix more refactor leftovers, test against actual ID

* Add the tracing fields under "correct" name as well

* Add log_record_factory and DRY some code

* Automatically install the log_record_factory

Plus add a test

* Update changelog

* Add more documentation about correlation

* s/elasticapm/The Elastic APM agent/

Co-Authored-By: Benjamin Wohlwend <[email protected]>

* Fix project-level import

Co-Authored-By: Benjamin Wohlwend <[email protected]>

* Apply suggestions from code review

Co-Authored-By: Brandon Morelli <[email protected]>

* Fix up tracing fields link

* Apply suggestions from code review

Co-Authored-By: Brandon Morelli <[email protected]>

* Separate log_record_factory tests from client instantiation

Also fix up some imports and assert elasticapm_labels everywhere

* More docs changes from reviews

* Fix another accidental relative import

* Use full link for ecs docs

* Fix for py2 testing

* Fix missing import (inline due to circular import)

* Remove standalone log_record_factory test

Because of the dynamic insertion in Client, this test was failing
on the wider integration tests (perhaps because it had been inserted
on previous test runs? I'm actually not sure). Anyway, we test
that it works with an instantiated Client so I think this test is
unnecessary.

* Apply suggestions from code review

Co-Authored-By: Benjamin Wohlwend <[email protected]>
Co-Authored-By: Andrew Wilkins <[email protected]>

* Implement config doc changes

* Fix structlog processor to skip None values

Author: basepi

CHANGELOG.md

@@ -3,6 +3,12 @@
 ## Unreleased
 [Check the diff](https://github.com/elastic/apm-agent-python/compare/v5.1.2...master)
 
+### New Features
+ * added automatic tagging of LogRecord objects with transaction, trace, and span IDs via a LogRecordFactory (Python 3.2+) (#520, #586)
+ * added `logging` filter and record factory for adding transaction, trace, and span IDs (#520, #586)
+ * added `structlog` processor for adding transaction, trace, and span IDs (#520, #586)
+ * added new public API calls for getting transaction, trace, and span IDs (#520, #586)
+
 ### Bugfixes
  * drop events immediately if a processor returns a falsy value (#585)
 
@@ -15,7 +21,7 @@
  * fixed zerorpc tests (#581)
  * fixed to correctly check if gevent has patched threading.local (#579)
 
-## v5.1.1 
+## v5.1.1
 [Check the diff](https://github.com/elastic/apm-agent-python/compare/v5.1.0...v5.1.1)
 
 ### Bugfixes
@@ -27,7 +33,7 @@
 ### Other
  * Added Python 3.8 RC to the test matrix (#565)
 
-## v5.1.0 
+## v5.1.0
 [Check the diff](https://github.com/elastic/apm-agent-python/compare/v5.0.0...v5.1.0)
 
 ### Security issues
@@ -46,7 +52,7 @@
  * fixed an issue with the `instrument` config option (#546, #547)
  * limited the amount of distinct metrics to 1000 (#540, #544)
 
-## v5.0.0 
+## v5.0.0
 [Check the diff](https://github.com/elastic/apm-agent-python/compare/v4.2.2...v5.0.0)
 ### Breaking changes
 
@@ -72,12 +78,12 @@
  * introduced `IntervalTimer` and use it instead of `threading.Timer` (#452)
  * added license header check as pre-commit hook (#456)
 
-## v4.2.1 
+## v4.2.1
 [Check the diff](https://github.com/elastic/apm-agent-python/compare/v4.2.0...v4.2.1)
  * fixed an issue with the certificate pinning feature introduced in 4.2.0 (#433, #434)
  * fixed incompatibility with eventlet introduced in 4.2.0 (#435, #436)
-    
-## v4.2.0 
+
+## v4.2.0
 [Check the diff](https://github.com/elastic/apm-agent-python/compare/v4.1.0...v4.2.0)
 
  * Implemented a new transport queue, which should avoid certain deadlock scenarios (#411)
@@ -90,7 +96,7 @@
  * Fixed an issue with parsing /proc/stat in RHEL/centos 6 (#406, #407)
  * Added copyright header to all files, and a CI check (#429)
 
-## v4.1.0 
+## v4.1.0
 [Check the diff](https://github.com/elastic/apm-agent-python/compare/v4.0.3...v4.1.0)
 
  * Added support for collecting system and process metrics (#361)
@@ -118,7 +124,7 @@
 
  * fixed an issue with instrumenting redis-py 3.0+
  * fixed a multithreading issue that occurs when using threaded workers (#335)
- 
+
 ## v4.0.0
 [Check the diff](https://github.com/elastic/apm-agent-python/compare/v3.0.2...v4.0.0)
 
@@ -143,14 +149,14 @@ Other changes:
 
  * fixed an issue with detecting names of wrapped functions that are partials (#294)
  * fixed a bug in Flask instrumentation that could appear together with FlaskAPI (#286)
- 
+
 ## v3.0.1
 
 [Check the diff](https://github.com/elastic/apm-agent-python/compare/v3.0.0...v3.0.1)
 
  * added sanitization for `Set-Cookie` response headers (#264)
  * added instrumentation for the non-standard `Connection.execute()` method for SQLite3 (#271)
- * added "authorization" to list of sensitive keywords, to ensure that "Authorization" 
+ * added "authorization" to list of sensitive keywords, to ensure that "Authorization"
    HTTP headers are properly sanitized (#275)
  * taught the Logbook handler how to handle the `stack=False` option (#278)
  * fixed a race condition with managing the timer-send thread (#279)
@@ -160,12 +166,12 @@ Other changes:
 [Check the diff](https://github.com/elastic/apm-agent-python/compare/v2.2.1...v3.0.0)
 
  - adapted "black" code formatter for this repository (#262)
- - **BREAKING**: dropped support for Python 3.3 (#242) 
+ - **BREAKING**: dropped support for Python 3.3 (#242)
  - **BREAKING**: changed order of precedence when evaluating configuration (#255, #261)
- - **BREAKING**: changed default value of `span_frames_min_duration` setting 
+ - **BREAKING**: changed default value of `span_frames_min_duration` setting
    from `-1` (always collect) to `5` (only collect for spans longer than 5 ms) (#243)
  - added instrumentation for pymssql (#241)
- - added instrumentation for pyodbc (#238) 
+ - added instrumentation for pyodbc (#238)
 
 ## v2.2.1
 

docs/advanced-topics.asciidoc

@@ -7,4 +7,5 @@
 
 include::./custom-instrumentation.asciidoc[Custom Instrumentation]
 include::./sanitizing-data.asciidoc[Sanitizing Data]
-include::./run-tests-locally.asciidoc[Run Tests Locally]
+include::./run-tests-locally.asciidoc[Run Tests Locally]
+include::./logging.asciidoc[Logging Integrations]

docs/api.asciidoc

@@ -174,7 +174,6 @@ elasticapm.set_transaction_name('myapp.billing_process')
  * `override`: if `True` (the default), overrides any previously set transaction name.
     If `False`, only sets the name if the transaction name hasn't already been set.
 
-
 [float]
 [[api-set-transaction-result]]
 ==== `elasticapm.set_transaction_result()`
@@ -194,6 +193,49 @@ elasticapm.set_transaction_result('SUCCESS')
  * `override`: if `True` (the default), overrides any previously set result.
     If `False`, only sets the result if the result hasn't already been set.
 
+
+[float]
+[[api-get-transaction-id]]
+==== `elasticapm.get_transaction_id()`
+
+Get the id of the current transaction. Example:
+
+[source,python]
+----
+import elasticapm
+
+transaction_id = elasticapm.get_transaction_id()
+----
+
+
+[float]
+[[api-get-trace-id]]
+==== `elasticapm.get_trace_id()`
+
+Get the `trace_id` of the current transaction's trace. Example:
+
+[source,python]
+----
+import elasticapm
+
+trace_id = elasticapm.get_trace_id()
+----
+
+
+[float]
+[[api-get-span-id]]
+==== `elasticapm.get_span_id()`
+
+Get the id of the current span. Example:
+
+[source,python]
+----
+import elasticapm
+
+span_id = elasticapm.get_span_id()
+----
+
+
 [float]
 [[api-set-custom-context]]
 ==== `elasticapm.set_custom_context()`

docs/configuration.asciidoc

@@ -679,6 +679,18 @@ Any labels set by application via the API will override global labels with the s
 
 NOTE: This feature requires APM Server >= 7.2.
 
+[float]
+[[config-generic-disable-log-record-factory]]
+==== `disable_log_record_factory`
+|============
+| Environment                              | Django/Flask                 | Default
+| `ELASTIC_APM_DISABLE_LOG_RECORD_FACTORY` | `DISABLE_LOG_RECORD_FACTORY` | `False`
+|============
+
+By default in python 3, the agent will install a <<logging,LogRecord factory>> that
+automatically adds tracing fields to your log records. You can disable this
+behavior by setting this to `True`.
+
 [float]
 [[config-django-specific]]
 === Django-specific configuration

docs/logging.asciidoc

@@ -0,0 +1,135 @@
+[[logging-integrations]]
+=== Logging integrations
+
+The Elastic APM agent provides integrations with both the default Python logging library,
+as well as http://www.structlog.org/en/stable/[`structlog`].
+
+[[logging]]
+==== `logging`
+
+For Python 3.2+, we use https://docs.python.org/3/library/logging.html#logging.setLogRecordFactory[`logging.setLogRecordFactory()`]
+to decorate the default LogRecordFactory to automatically add new attributes to
+each LogRecord object:
+
+* `elasticapm_transaction_id`
+* `elasticapm_trace_id`
+* `elasticapm_span_id`
+
+This factory also adds these fields to a dictionary attribute,
+`elasticapm_labels`, using the official ECS https://www.elastic.co/guide/en/ecs/current/ecs-tracing.html[tracing fields].
+
+You can disable this automatic behavior by using the
+<<config-generic-disable-log-record-factory,`disable_log_record_factory`>> setting
+in your configuration
+
+For Python versions <3.2, we also provide a
+https://docs.python.org/3/library/logging.html#filter-objects[filter] which will
+add the same new attributes to any filtered `LogRecord`:
+
+Note: Because https://docs.python.org/3/library/logging.html#filter-objects[filters
+are not propagated to descendent loggers], you should add the filter to each of
+your log handlers, as handlers are propagated, along with their attached filters.
+
+[source,python]
+----
+import logging
+from elasticapm.handlers.logging import LoggingFilter
+
+console = logging.StreamHandler()
+console.addFilter(LoggingFilter())
+# add the handler to the root logger
+logging.getLogger("").addHandler(console)
+----
+
+
+[[structlog]]
+==== `structlog`
+
+We provide a http://www.structlog.org/en/stable/processors.html[processor] for
+http://www.structlog.org/en/stable/[`structlog`] which will add three new keys
+to the event_dict of any processed event:
+
+* `transaction.id`
+* `trace.id`
+* `span.id`
+
+[source,python]
+----
+from structlog import PrintLogger, wrap_logger
+from elasticapm.handlers.structlog import structlog_processor
+
+wrapped_logger = PrintLogger()
+logger = wrap_logger(wrapped_logger, processors=[structlog_processor])
+log = logger.new()
+log.msg("some_event")
+----
+
+
+[[log-correlation]]
+=== Log correlation in Elasticsearch
+
+In order to correlate logs from your app with transactions captured by the
+Elastic APM Python Agent, your logs must contain one or more of the following
+identifiers:
+
+* `transaction.id`
+* `trace.id`
+* `span.id`
+
+If you're using structured logging, either https://docs.python.org/3/howto/logging-cookbook.html#implementing-structured-logging[with a custom solution]
+or with http://www.structlog.org/en/stable/[structlog] (recommended), then this
+is fairly easy. Throw the http://www.structlog.org/en/stable/api.html#structlog.processors.JSONRenderer[JSONRenderer]
+in, and use {blog-ref}structured-logging-filebeat[Filebeat]
+to pull these logs into Elasticsearch.
+
+Without structured logging the task gets a little trickier. Here we
+recommend first making sure your LogRecord objects have the elasticapm
+attributes (see <<logging>>), and then you'll want to combine some specific
+formatting with a Grok pattern, either in Elasticsearch using
+{ref}/grok-processor.html[the grok processor],
+or in {logstash-ref}/plugins-filters-grok.html[logstash with a plugin].
+
+Say you have a https://docs.python.org/3/library/logging.html#logging.Formatter[Formatter]
+that looks like this:
+
+[source,python]
+----
+import logging
+
+formatter = logging.Formatter("%(asctime)s - %(name)s - %(levelname)s - %(message)s")
+----
+
+You can add the APM identifiers in an easy-to-parse manner:
+
+[source,python]
+----
+import logging
+
+format_string = (
+    "%(asctime)s - %(name)s - %(levelname)s - %(message)s "
+    "| elasticapm "
+    "transaction.id=%(elasticapm_transaction_id) "
+    "trace.id=%(elasticapm_trace_id) "
+    "span.id=%(elasticapm_span_id)"
+)
+formatter = logging.Formatter(format_string)
+----
+
+Then, you could use a grok pattern like this (for the
+{ref}/grok-processor.html[Elasticsearch Grok Processor]):
+
+
+[source, json]
+----
+{
+  "description" : "...",
+  "processors": [
+    {
+      "grok": {
+        "field": "message",
+        "patterns": ["%{GREEDYDATA:msg} | elasticapm transaction.id=%{DATA:transaction.id} trace.id=%{DATA:trace.id} span.id=%{DATA:span.id}"]
+      }
+    }
+  ]
+}
+----

elasticapm/__init__.py

@@ -42,3 +42,4 @@
 from elasticapm.traces import capture_span, set_context, set_custom_context  # noqa: F401
 from elasticapm.traces import set_transaction_name, set_user_context, tag, label  # noqa: F401
 from elasticapm.traces import set_transaction_result  # noqa: F401
+from elasticapm.traces import get_transaction_id, get_trace_id, get_span_id  # noqa: F401

elasticapm/base.py

@@ -103,6 +103,21 @@ def __init__(self, config=None, **inline):
             config.disable_send = True
         self.config = VersionedConfig(config, version=None)
 
+        # Insert the log_record_factory into the logging library
+        # The LogRecordFactory functionality is only available on python 3.2+
+        if compat.PY3 and not self.config.disable_log_record_factory:
+            record_factory = logging.getLogRecordFactory()
+            # Only way to know if it's wrapped is to create a log record
+            throwaway_record = record_factory(__name__, logging.DEBUG, __file__, 252, "dummy_msg", [], None)
+            if not hasattr(throwaway_record, "elasticapm_labels"):
+                self.logger.debug("Inserting elasticapm log_record_factory into logging")
+
+                # Late import due to circular imports
+                import elasticapm.handlers.logging as elastic_logging
+
+                new_factory = elastic_logging.log_record_factory(record_factory)
+                logging.setLogRecordFactory(new_factory)
+
         headers = {
             "Content-Type": "application/x-ndjson",
             "Content-Encoding": "gzip",

elasticapm/conf/__init__.py

@@ -329,6 +329,7 @@ class Config(_ConfigBase):
     enable_distributed_tracing = _BoolConfigValue("ENABLE_DISTRIBUTED_TRACING", default=True)
     capture_headers = _BoolConfigValue("CAPTURE_HEADERS", default=True)
     django_transaction_name_from_route = _BoolConfigValue("DJANGO_TRANSACTION_NAME_FROM_ROUTE", default=False)
+    disable_log_record_factory = _BoolConfigValue("DISABLE_LOG_RECORD_FACTORY", default=False)
 
 
 class VersionedConfig(object):