ref: Improve errors when scope stack is broken (#194)

* ref: Improve errors when scope stack is broken

* ref: Named scopes for debugging

* fix: Tests

Author: untitaker

sentry_sdk/hub.py

@@ -80,19 +80,41 @@ def __exit__(self, exc_type, exc_value, tb):
 
 
 class _ScopeManager(object):
-    def __init__(self, hub, layer):
+    def __init__(self, hub):
         self._hub = hub
-        self._layer = layer
+        self._original_len = len(hub._stack)
+        self._layer = hub._stack[-1]
 
     def __enter__(self):
         scope = self._layer[1]
         assert scope is not None
         return scope
 
     def __exit__(self, exc_type, exc_value, tb):
-        layer = self._hub.pop_scope_unsafe()
-        assert layer[1] == self._layer[1], "popped wrong scope"
-        if layer[0] != self._layer[0]:
+        current_len = len(self._hub._stack)
+        if current_len < self._original_len:
+            logger.error(
+                "Scope popped too soon. Popped %s scopes too many.",
+                self._original_len - current_len,
+            )
+            return
+        elif current_len > self._original_len:
+            logger.warning(
+                "Leaked %s scopes: %s",
+                current_len - self._original_len,
+                self._hub._stack[self._original_len :],
+            )
+
+        layer = self._hub._stack[self._original_len - 1]
+        del self._hub._stack[self._original_len - 1 :]
+
+        if layer[1] != self._layer[1]:
+            logger.error(
+                "Wrong scope found. Meant to pop %s, but popped %s.",
+                layer[1],
+                self._layer[1],
+            )
+        elif layer[0] != self._layer[0]:
             warning = (
                 "init() called inside of pushed scope. This might be entirely "
                 "legitimate but usually occurs when initializing the SDK inside "
@@ -288,7 +310,7 @@ def push_scope(self, callback=None):
         new_layer = (client, copy.copy(scope))
         self._stack.append(new_layer)
 
-        return _ScopeManager(self, new_layer)
+        return _ScopeManager(self)
 
     scope = push_scope
 

sentry_sdk/integrations/flask.py

@@ -62,6 +62,8 @@ def _push_appctx(*args, **kwargs):
         # always want to push scope regardless of whether WSGI app might already
         # have (not the case for CLI for example)
         hub.push_scope()
+        with hub.configure_scope() as scope:
+            scope._name = "flask"
 
 
 def _pop_appctx(*args, **kwargs):

sentry_sdk/integrations/wsgi.py

@@ -61,6 +61,7 @@ def __call__(self, environ, start_response):
         hub.push_scope()
         with capture_internal_exceptions():
             with hub.configure_scope() as scope:
+                scope._name = "wsgi"
                 scope.add_event_processor(_make_wsgi_event_processor(environ))
 
         try:

sentry_sdk/scope.py

@@ -23,6 +23,7 @@ class Scope(object):
 
     __slots__ = (
         "_level",
+        "_name",
         "_fingerprint",
         "_transaction",
         "_user",
@@ -38,6 +39,7 @@ def __init__(self):
         self._event_processors = []
         self._error_processors = []
 
+        self._name = None
         self.clear()
 
     @_attr_setter
@@ -174,6 +176,7 @@ def __copy__(self):
         rv = object.__new__(self.__class__)
 
         rv._level = self._level
+        rv._name = self._name
         rv._fingerprint = self._fingerprint
         rv._transaction = self._transaction
         rv._user = self._user
@@ -187,3 +190,10 @@ def __copy__(self):
         rv._error_processors = list(self._error_processors)
 
         return rv
+
+    def __repr__(self):
+        return "<%s id=%s name=%s>" % (
+            self.__class__.__name__,
+            hex(id(self)),
+            self._name,
+        )

tests/test_basics.py

@@ -226,7 +226,7 @@ def test_integration_scoping():
     assert len(events) == 1
 
 
-def test_client_initialized_within_scope(sentry_init, capture_events, caplog):
+def test_client_initialized_within_scope(sentry_init, caplog):
     caplog.set_level(logging.WARNING)
 
     sentry_init(debug=True)
@@ -237,3 +237,37 @@ def test_client_initialized_within_scope(sentry_init, capture_events, caplog):
     record, = (x for x in caplog.records if x.levelname == "WARNING")
 
     assert record.msg.startswith("init() called inside of pushed scope.")
+
+
+def test_scope_leaks_cleaned_up(sentry_init, caplog):
+    caplog.set_level(logging.WARNING)
+
+    sentry_init(debug=True)
+
+    old_stack = list(Hub.current._stack)
+
+    with push_scope():
+        push_scope()
+
+    assert Hub.current._stack == old_stack
+
+    record, = (x for x in caplog.records if x.levelname == "WARNING")
+
+    assert record.message.startswith("Leaked 1 scopes:")
+
+
+def test_scope_popped_too_soon(sentry_init, caplog):
+    caplog.set_level(logging.ERROR)
+
+    sentry_init(debug=True)
+
+    old_stack = list(Hub.current._stack)
+
+    with push_scope():
+        Hub.current.pop_scope_unsafe()
+
+    assert Hub.current._stack == old_stack
+
+    record, = (x for x in caplog.records if x.levelname == "ERROR")
+
+    assert record.message == ("Scope popped too soon. Popped 1 scopes too many.")