Support logging payload when sending to socket or error service. (#727)

Author: tim-schilling

CHANGELOG.md

@@ -3,6 +3,9 @@
 ## Pending
 
 ### Added
+- Add `log_payload_content` to support logging the content of the message
+  being sent to either the core agent socket or the error service.
+  ([Issue 724](https://github.com/scoutapp/scout_apm_python/issues/724))
 
 ### Fixed
 

src/scout_apm/core/config.py

@@ -81,6 +81,7 @@ def log(self):
         "ignore",
         "key",
         "log_level",
+        "log_payload_content",
         "monitor",
         "name",
         "revision_sha",
@@ -231,6 +232,7 @@ def __init__(self):
             "framework_version": "",
             "hostname": None,
             "key": "",
+            "log_payload_content": False,
             "monitor": False,
             "name": "Python App",
             "revision_sha": self._git_revision_sha(),

src/scout_apm/core/error.py

@@ -1,6 +1,7 @@
 # coding=utf-8
 from __future__ import absolute_import, division, print_function, unicode_literals
 
+import logging
 import sys
 
 from scout_apm.core.backtrace import capture_stacktrace
@@ -9,6 +10,7 @@
 from scout_apm.core.tracked_request import TrackedRequest
 from scout_apm.core.web_requests import RequestComponents, filter_element
 
+logger = logging.getLogger(__name__)
 text_type = str if sys.version_info[0] >= 3 else unicode  # noqa: F821
 
 
@@ -80,4 +82,13 @@ def send(
             "revision_sha": scout_config.value("revision_sha"),
         }
 
+        if scout_config.value("log_payload_content"):
+            logger.debug(
+                "Sending error for request: %s. Payload: %r",
+                tracked_request.request_id,
+                error,
+            )
+        else:
+            logger.debug("Sending error for request: %s.", tracked_request.request_id)
+
         ErrorServiceThread.send(error=error)

src/scout_apm/core/tracked_request.py

@@ -9,6 +9,7 @@
 from scout_apm.core import backtrace, objtrace
 from scout_apm.core.agent.commands import BatchCommand
 from scout_apm.core.agent.socket import CoreAgentSocketThread
+from scout_apm.core.config import scout_config
 from scout_apm.core.n_plus_one_tracker import NPlusOneTracker
 from scout_apm.core.samplers.memory import get_rss_in_mb
 from scout_apm.core.samplers.thread import SamplersThread
@@ -151,8 +152,15 @@ def finish(self):
             self.tag("mem_delta", self._get_mem_delta())
             if not self.is_ignored() and not self.sent:
                 self.sent = True
-                logger.debug("Sending request: %s", self.request_id)
                 batch_command = BatchCommand.from_tracked_request(self)
+                if scout_config.value("log_payload_content"):
+                    logger.debug(
+                        "Sending request: %s. Payload: %s",
+                        self.request_id,
+                        batch_command.message(),
+                    )
+                else:
+                    logger.debug("Sending request: %s.", self.request_id)
                 CoreAgentSocketThread.send(batch_command)
             SamplersThread.ensure_started()
 

tests/unit/core/test_error.py

@@ -1,6 +1,7 @@
 # coding=utf-8
 from __future__ import absolute_import, division, print_function, unicode_literals
 
+import logging
 import sys
 from contextlib import contextmanager
 
@@ -168,6 +169,7 @@ def test_monitor(
     expected_error,
     tracked_request,
     error_monitor_errors,
+    caplog,
 ):
     with app_with_scout():
         tracked_request.request_id = "sample_id"
@@ -197,3 +199,49 @@ def test_monitor(
     assert line
     assert func_str == "in test_monitor"
     assert error == expected_error
+    assert (
+        "scout_apm.core.error",
+        logging.DEBUG,
+        "Sending error for request: sample_id.",
+    ) in caplog.record_tuples
+
+
+def test_monitor_with_logged_payload(
+    tracked_request,
+    error_monitor_errors,
+    caplog,
+):
+    with app_with_scout(scout_config={"log_payload_content": True}):
+        tracked_request.request_id = "sample_id"
+        tracked_request.tags["spam"] = "foo"
+        exc_info = 0
+        try:
+            1 / 0
+        except ZeroDivisionError:
+            exc_info = sys.exc_info()
+        ErrorMonitor.send(
+            exc_info,
+            request_components=RequestComponents("sample.app", "DataView", "detail"),
+            request_path="/test/",
+        )
+
+    assert len(error_monitor_errors) == 1
+
+    # Find the logged message.
+    actual_message = None
+    for module, level, message in caplog.record_tuples:
+        if module == "scout_apm.core.error" and level == logging.DEBUG:
+            if message.startswith("Sending error for request: sample_id. Payload: "):
+                actual_message = message
+                break
+    assert actual_message
+
+    assert "ZeroDivisionError" in actual_message
+    assert "division by zero" in actual_message
+    assert (
+        "tests/unit/core/test_error.py:219:in test_monitor_with_logged_payload"
+        in actual_message
+    )
+    assert "sample.app" in actual_message
+    assert "DataView" in actual_message
+    assert "/test/" in actual_message

tests/unit/core/test_tracked_request.py

@@ -5,7 +5,10 @@
 import logging
 import sys
 
+import pytest
+
 from scout_apm.core import objtrace
+from scout_apm.core.config import scout_config
 from scout_apm.core.tracked_request import TrackedRequest
 from tests.compat import copy_context, mock
 from tests.tools import (
@@ -15,6 +18,18 @@
 )
 
 
+@pytest.fixture
+def reset_config():
+    """
+    Reset scout configuration after a test
+    """
+    try:
+        yield
+    finally:
+        # Reset Scout configuration.
+        scout_config.reset_all()
+
+
 def test_tracked_request_repr(tracked_request):
     assert repr(tracked_request).startswith("<TrackedRequest(")
 
@@ -214,7 +229,7 @@ def test_finish_log_request_info(tracked_request, caplog):
     assert (
         "scout_apm.core.tracked_request",
         logging.DEBUG,
-        "Sending request: {}".format(tracked_request.request_id),
+        "Sending request: {}.".format(tracked_request.request_id),
     ) in caplog.record_tuples
 
     assert (
@@ -237,6 +252,42 @@ def test_finish_log_request_info(tracked_request, caplog):
     ) in caplog.record_tuples
 
 
+def test_finish_log_request_info_with_logged_payload(
+    tracked_request, caplog, reset_config
+):
+    scout_config.set(log_payload_content=True)
+    tracked_request.is_real_request = True
+    tracked_request.start_span(operation="Something")
+    tracked_request.stop_span()
+
+    # Find the logged message.
+    actual_message = None
+    for module, level, message in caplog.record_tuples:
+        if module == "scout_apm.core.tracked_request" and level == logging.DEBUG:
+            if message.startswith(
+                "Sending request: {}. Payload: ".format(tracked_request.request_id)
+            ):
+                actual_message = message
+                break
+    assert actual_message
+    # Verify the counts of the spans and the request id.
+    assert actual_message.count("'StartRequest'") == 1
+    assert actual_message.count("'FinishRequest'") == 1
+    assert actual_message.count("'TagRequest'") == 1
+    assert actual_message.count("'StartSpan'") == 1
+    assert actual_message.count("'StopSpan'") == 1
+    if objtrace.is_extension:
+        assert actual_message.count("'TagSpan'") == 3
+        total_requests = 8
+    else:
+        assert actual_message.count("'TagSpan'") == 0
+        total_requests = 5
+    # Verify each request id in the payload is the tracked request's.
+    assert actual_message.count("'request_id'") == total_requests
+    # The actual request id is also included in the log message after Sending request:
+    assert actual_message.count(tracked_request.request_id) == total_requests + 1
+
+
 def test_finish_clears_context():
     tracked_request_1 = TrackedRequest.instance()
     tracked_request_1.is_real_request = True
@@ -273,7 +324,7 @@ def test_request_only_sent_once(tracked_request, caplog):
     sent_log = (
         "scout_apm.core.tracked_request",
         logging.DEBUG,
-        "Sending request: {}".format(tracked_request.request_id),
+        "Sending request: {}.".format(tracked_request.request_id),
     )
     info_log = (
         "scout_apm.core.tracked_request",