Add logging Formatter class (#595)

* Add logging Formatter class

We need a custom Formatter class in order to add error handling for
any logs which happen before the Client is initialized (and our
LogRecordFactory is put into place).

* Remove some unused imports

* Add leading space for consistency with recommended grok pattern

* py2 compat

* Update bullets to match sidebar

Author: basepi

docs/advanced-topics.asciidoc

@@ -4,6 +4,8 @@
 * <<instrumenting-custom-code>>
 * <<sanitizing-data>>
 * <<run-tests-locally>>
+* <<logging-integrations>>
+* <<log-correlation>>
 
 include::./custom-instrumentation.asciidoc[Custom Instrumentation]
 include::./sanitizing-data.asciidoc[Sanitizing Data]

docs/logging.asciidoc

@@ -96,23 +96,33 @@ that looks like this:
 ----
 import logging
 
+fh = logging.FileHandler('spam.log')
 formatter = logging.Formatter("%(asctime)s - %(name)s - %(levelname)s - %(message)s")
+fh.setFormatter(formatter)
 ----
 
-You can add the APM identifiers in an easy-to-parse manner:
+You can add the APM identifiers by simply switching out the `Formatter` object
+for the one that we provide:
 
 [source,python]
 ----
 import logging
+from elasticapm.handlers.logging import Formatter
 
-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)
+fh = logging.FileHandler('spam.log')
+formatter = Formatter("%(asctime)s - %(name)s - %(levelname)s - %(message)s")
+fh.setFormatter(formatter)
+----
+
+This will automatically append apm-specific fields to your format string:
+
+[source,python]
+----
+formatstring = "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
+formatstring = formatstring + " | elasticapm " \
+                              "transaction.id=%(elasticapm_transaction_id)s " \
+                              "trace.id=%(elasticapm_trace_id)s " \
+                              "span.id=%(elasticapm_span_id)s"
 ----
 
 Then, you could use a grok pattern like this (for the

elasticapm/handlers/logging.py

@@ -223,3 +223,46 @@ def _add_attributes_to_log_record(record):
     record.elasticapm_labels = {"transaction.id": transaction_id, "trace.id": trace_id, "span.id": span_id}
 
     return record
+
+
+class Formatter(logging.Formatter):
+    """
+    Custom formatter to automatically append the elasticapm format string,
+    as well as ensure that LogRecord objects actually have the required fields
+    (so as to avoid errors which could occur for logs before we override the
+    LogRecordFactory):
+
+        formatstring = "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
+        formatstring = formatstring + " | elasticapm " \
+                                      "transaction.id=%(elasticapm_transaction_id)s " \
+                                      "trace.id=%(elasticapm_trace_id)s " \
+                                      "span.id=%(elasticapm_span_id)s"
+    """
+
+    def __init__(self, fmt=None, datefmt=None, style="%"):
+        if fmt is None:
+            fmt = "%(message)s"
+        fmt = (
+            fmt + " | elasticapm "
+            "transaction.id=%(elasticapm_transaction_id)s "
+            "trace.id=%(elasticapm_trace_id)s "
+            "span.id=%(elasticapm_span_id)s"
+        )
+        if compat.PY3:
+            super(Formatter, self).__init__(fmt=fmt, datefmt=datefmt, style=style)
+        else:
+            super(Formatter, self).__init__(fmt=fmt, datefmt=datefmt)
+
+    def format(self, record):
+        if not hasattr(record, "elasticapm_transaction_id"):
+            record.elasticapm_transaction_id = None
+            record.elasticapm_trace_id = None
+            record.elasticapm_span_id = None
+        return super(Formatter, self).format(record=record)
+
+    def formatTime(self, record, datefmt=None):
+        if not hasattr(record, "elasticapm_transaction_id"):
+            record.elasticapm_transaction_id = None
+            record.elasticapm_trace_id = None
+            record.elasticapm_span_id = None
+        return super(Formatter, self).formatTime(record=record, datefmt=datefmt)

tests/handlers/logging/logging_tests.py

@@ -36,9 +36,9 @@
 
 from elasticapm.conf import Config
 from elasticapm.conf.constants import ERROR
-from elasticapm.handlers.logging import LoggingFilter, LoggingHandler, log_record_factory
+from elasticapm.handlers.logging import Formatter, LoggingFilter, LoggingHandler
 from elasticapm.handlers.structlog import structlog_processor
-from elasticapm.traces import Tracer, capture_span, execution_context
+from elasticapm.traces import Tracer, capture_span
 from elasticapm.utils import compat
 from elasticapm.utils.stacks import iter_stack_frames
 from tests.fixtures import TempStoreClient
@@ -313,3 +313,15 @@ def test_automatic_log_record_factory_install(elasticapm_client):
         assert record.elasticapm_trace_id == transaction.trace_parent.trace_id
         assert record.elasticapm_span_id == span.id
         assert record.elasticapm_labels
+
+
+def test_formatter():
+    record = logging.LogRecord(__name__, logging.DEBUG, __file__, 252, "dummy_msg", [], None)
+    formatter = Formatter()
+    formatted_record = formatter.format(record)
+    assert "| elasticapm" in formatted_record
+    assert hasattr(record, "elasticapm_transaction_id")
+    record = logging.LogRecord(__name__, logging.DEBUG, __file__, 252, "dummy_msg", [], None)
+    formatted_time = formatter.formatTime(record)
+    assert formatted_time
+    assert hasattr(record, "elasticapm_transaction_id")