Browse Source

ref: instrument pickle unicode fallback with sentry (#67276)

we're still seeing some hits on the metrics for `loads` and
`Unpickler.load`

unclear where they're coming from so I'm going to instrument this with
sentry to figure it out

I've hidden this behaviour behind a feature flag so I can turn it on
once rolled out (as I would expect these to be new sentry issues and
would block canary / etc. if triggered)

here's what the resulting sentry errors will look like since I need to
do some fudging around in `logging` to make them include a fulltrace and
the original error message:

<img width="1427" alt="Screenshot 2024-03-19 at 4 21 37 PM"
src="https://github.com/getsentry/sentry/assets/103459774/04011ff5-1d6a-4bf7-a42a-4107b93f79eb">
<img width="1089" alt="Screenshot 2024-03-19 at 4 22 25 PM"
src="https://github.com/getsentry/sentry/assets/103459774/babcacf2-872d-4ea9-af0a-75b86e31e9a5">


<!-- Describe your PR here. -->
anthony sottile 11 months ago
parent
commit
4762832181

+ 24 - 13
src/sentry/monkey/pickle.py

@@ -48,6 +48,23 @@
 # [0]: https://rebeccabilbro.github.io/convert-py2-pickles-to-py3/#python-2-objects-vs-python-3-objects
 
 
+def _record_pickle_failure(metric_name: str, e: Exception) -> None:
+    from sentry.utils import metrics
+
+    metrics.incr(metric_name, sample_rate=1)
+
+    import random
+
+    from sentry import options
+
+    if options.get("pickle.send-error-to-sentry") >= random.random():
+        import logging
+
+        msg = f"{metric_name}.{type(e).__name__}: {e}"
+        # exc_info=(None, None, None) gives us a full traceback
+        logging.getLogger(__name__).error(msg, exc_info=(None, None, None))
+
+
 def patch_pickle_loaders():
     import pickle
 
@@ -76,11 +93,9 @@ def patch_pickle_loaders():
         def load(self):
             try:
                 return self.__unpickler.load()
-            except UnicodeDecodeError:
-                from sentry.utils import metrics
-
-                metrics.incr(
-                    "pickle.compat_pickle_pickler_load.had_unicode_decode_error", sample_rate=1
+            except UnicodeDecodeError as e:
+                _record_pickle_failure(
+                    "pickle.compat_pickle_pickler_load.had_unicode_decode_error", e
                 )
 
                 # We must seek back to the start of the buffer to depickle
@@ -98,10 +113,8 @@ def patch_pickle_loaders():
     def py3_compat_pickle_load(*args, **kwargs):
         try:
             return original_pickle_load(*args, **kwargs)
-        except UnicodeDecodeError:
-            from sentry.utils import metrics
-
-            metrics.incr("pickle.compat_pickle_load.had_unicode_decode_error", sample_rate=1)
+        except UnicodeDecodeError as e:
+            _record_pickle_failure("pickle.compat_pickle_load.had_unicode_decode_error", e)
 
             kwargs["encoding"] = kwargs.get("encoding", "latin-1")
             return original_pickle_load(*args, **kwargs)
@@ -109,10 +122,8 @@ def patch_pickle_loaders():
     def py3_compat_pickle_loads(*args, **kwargs):
         try:
             return original_pickle_loads(*args, **kwargs)
-        except UnicodeDecodeError:
-            from sentry.utils import metrics
-
-            metrics.incr("pickle.compat_pickle_loads.had_unicode_decode_error", sample_rate=1)
+        except UnicodeDecodeError as e:
+            _record_pickle_failure("pickle.compat_pickle_loads.had_unicode_decode_error", e)
 
             kwargs["encoding"] = kwargs.get("encoding", "latin-1")
             return original_pickle_loads(*args, **kwargs)

+ 7 - 0
src/sentry/options/defaults.py

@@ -2165,6 +2165,13 @@ register(
     flags=FLAG_AUTOMATOR_MODIFIABLE,
 )
 
+# sample rate for pickle error collection
+register(
+    "pickle.send-error-to-sentry",
+    default=0.0,
+    flags=FLAG_AUTOMATOR_MODIFIABLE,
+)
+
 # killswitch for profiling ddm functions metrics.
 # Enable/Disable the ingestion of function metrics
 # in the generic metrics platform

+ 0 - 0
tests/sentry/monkey/__init__.py


+ 35 - 0
tests/sentry/monkey/test_pickle.py

@@ -0,0 +1,35 @@
+import pickle
+
+import pytest
+
+from sentry.testutils.helpers.options import override_options
+
+
+@pytest.fixture(autouse=True)
+def assert_using_monkeypatched_pickle():
+    assert pickle.loads.__module__.startswith("sentry.")
+
+
+def _load_bad_pickle():
+    # a python 2 pickle of `u'\u2603'.encode('UTF-8')` with protocol 2
+    # results in mojibake
+    assert pickle.loads(b"\x80\x02U\x03\xe2\x98\x83q\x00.") == "â\x98\x83"
+
+
+@override_options({"pickle.send-error-to-sentry": 0})
+def test_pickle_loads_no_logging_to_sentry_when_disabled(caplog):
+    _load_bad_pickle()
+
+    # no sentry logging when we have disabled the option
+    assert not caplog.records
+
+
+@override_options({"pickle.send-error-to-sentry": 1})
+def test_pickle_loads_logging_to_sentry(caplog):
+    _load_bad_pickle()
+
+    (record,) = caplog.records
+    assert record.levelname == "ERROR"
+    assert record.exc_info == (None, None, None)
+    expected = "pickle.compat_pickle_loads.had_unicode_decode_error.UnicodeDecodeError: 'ascii' codec can't decode byte 0xe2 in position 0: ordinal not in range(128)"
+    assert record.message == expected