Browse Source

fix(server): Suppress errors in logging when in Prod (#60131)

Suppress exceptions coming from the logging itself when in Production. 
Related to INC-564, Epic #60225

This doesn't fix the underlying issue, just suppresses the errors to
prevent production outages.
We need a separate hack to make JSONEncoder handle non-standard keys. 

- Implements #60224
- Enabling `skipkeys` serves as a workaround for #60227 not being
viable.
Bartek Ogryczak 1 year ago
parent
commit
68d10b7a42

+ 37 - 16
src/sentry/logging/handlers.py

@@ -7,18 +7,6 @@ from structlog.processors import _json_fallback_handler
 
 from sentry.utils import json, metrics
 
-_default_encoder = json.JSONEncoder(
-    separators=(",", ":"),
-    ignore_nan=True,
-    skipkeys=False,
-    ensure_ascii=True,
-    check_circular=True,
-    allow_nan=True,
-    indent=None,
-    encoding="utf-8",
-    default=_json_fallback_handler,
-).encode
-
 # These are values that come default from logging.LogRecord.
 # They are defined here:
 # https://github.com/python/cpython/blob/2.7/Lib/logging/__init__.py#L237-L310
@@ -45,9 +33,38 @@ throwaways = frozenset(
 )
 
 
+def _json_encoder(*, skipkeys: bool = False) -> json.JSONEncoder:
+    return json.JSONEncoder(
+        separators=(",", ":"),
+        ignore_nan=True,
+        skipkeys=skipkeys,
+        ensure_ascii=True,
+        check_circular=True,
+        allow_nan=True,
+        indent=None,
+        encoding="utf-8",
+        default=_json_fallback_handler,
+    )
+
+
+_json_encoder_skipkeys = _json_encoder(skipkeys=True)
+_json_encoder_no_skipkeys = _json_encoder(skipkeys=False)
+
+
 class JSONRenderer:
     def __call__(self, logger, name, event_dict):
-        return _default_encoder(event_dict)
+        # importing inside of the function to avoid circular imports
+        from django.conf import settings
+
+        try:
+            return _json_encoder_no_skipkeys.encode(event_dict)
+        except Exception:
+            logging.warning("Failed to serialize event", exc_info=True)
+            # in Production, we want to skip non-serializable keys, rather than raise an exception
+            if settings.DEBUG:
+                raise
+            else:
+                return _json_encoder_skipkeys.encode(event_dict)
 
 
 class HumanRenderer:
@@ -87,9 +104,13 @@ class StructLogHandler(logging.StreamHandler):
         # structlog, we have to strip all of the default attributes from
         # a record because the RootLogger will take the 'extra' dictionary
         # and just turn them into attributes.
-        if logger is None:
-            logger = get_logger()
-        logger.log(**self.get_log_kwargs(record=record, logger=logger))
+        try:
+            if logger is None:
+                logger = get_logger()
+            logger.log(**self.get_log_kwargs(record=record, logger=logger))
+        except Exception:
+            if logging.raiseExceptions:
+                raise
 
 
 class MessageContainsFilter(logging.Filter):

+ 2 - 0
src/sentry/runner/initializer.py

@@ -325,6 +325,8 @@ def initialize_app(config: dict[str, Any], skip_service_validation: bool = False
 
     bootstrap_options(settings, config["options"])
 
+    logging.raiseExceptions = settings.DEBUG
+
     configure_structlog()
 
     # Commonly setups don't correctly configure themselves for production envs

+ 53 - 1
tests/sentry/logging/test_handler.py

@@ -4,7 +4,7 @@ from unittest import mock
 
 import pytest
 
-from sentry.logging.handlers import StructLogHandler
+from sentry.logging.handlers import JSONRenderer, StructLogHandler
 
 
 @pytest.fixture
@@ -17,6 +17,15 @@ def logger():
     return mock.MagicMock()
 
 
+@pytest.fixture
+def snafu() -> Any:
+    class SNAFU:
+        def __str__(self) -> str:
+            raise Exception("snafu")
+
+    return SNAFU()
+
+
 def make_logrecord(
     *,
     name: str = "name",
@@ -67,3 +76,46 @@ def test_log_to_metric(metrics):
 
     logger.warning("Some other problem we don't care about")
     assert metrics.incr.call_count == 0
+
+
+@mock.patch("logging.raiseExceptions", True)
+def test_emit_invalid_keys_nonprod(handler):
+    logger = mock.MagicMock()
+    logger.log.side_effect = TypeError("invalid keys")
+    with pytest.raises(TypeError):
+        handler.emit(make_logrecord(), logger=logger)
+
+
+@mock.patch("logging.raiseExceptions", False)
+def test_emit_invalid_keys_prod(handler):
+    logger = mock.MagicMock()
+    logger.log.side_effect = TypeError("invalid keys")
+    handler.emit(make_logrecord(), logger=logger)
+
+
+@mock.patch("django.conf.settings.DEBUG", True)
+def test_JSONRenderer_nonprod():
+    renderer = JSONRenderer()
+    with pytest.raises(TypeError):
+        renderer(None, None, {"foo": {mock.Mock(): "foo"}})
+
+
+@mock.patch("django.conf.settings.DEBUG", False)
+def test_JSONRenderer_prod():
+    renderer = JSONRenderer()
+    renderer(None, None, {"foo": {mock.Mock(): "foo"}})
+
+
+@mock.patch("logging.raiseExceptions", True)
+def test_logging_raiseExcpetions_enabled_generic_logging(caplog, snafu):
+    logger = logging.getLogger(__name__)
+
+    with pytest.raises(Exception) as exc_info:
+        logger.log(logging.INFO, snafu)
+    assert exc_info.value.args == ("snafu",)
+
+
+@mock.patch("logging.raiseExceptions", False)
+def test_logging_raiseExcpetions_disabled_generic_logging(caplog, snafu):
+    logger = logging.getLogger(__name__)
+    logger.log(logging.INFO, snafu)