honeybadger-io / honeybadger-python

Send Python and Django errors to Honeybadger.
https://www.honeybadger.io/
MIT License
15 stars 26 forks source link

500 Error created by Honeybadger send_notice #165

Closed payala closed 7 months ago

payala commented 8 months ago

I think this is probably a honeybadger edge-case bug.

There is an endpoint which I’m hitting badly intentionally, it should return a 422 because I’m passing 1234 instead of a valid guid.

It works well in my local test environment because hb is disabled in local, but in production, where honey badger is enabled it results in a 500 error, and no notice is sent to hb, because it is failing in the notification sending itself. This is the error trace I see in the server:

ERROR:    Exception in ASGI application
agiliza-web-1      | Traceback (most recent call last):
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/honeybadger/contrib/asgi.py", line 115, in _run_app
agiliza-web-1      |     return await callback()
agiliza-web-1      |            ^^^^^^^^^^^^^^^^
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/starlette/middleware/base.py", line 189, in __call__
agiliza-web-1      |     with collapse_excgroups():
agiliza-web-1      |   File "/usr/local/lib/python3.11/contextlib.py", line 155, in __exit__
agiliza-web-1      |     self.gen.throw(typ, value, traceback)
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/starlette/_utils.py", line 91, in collapse_excgroups
agiliza-web-1      |     raise exc
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/starlette/middleware/base.py", line 191, in __call__
agiliza-web-1      |     response = await self.dispatch_func(request, call_next)
agiliza-web-1      |                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/starlette_prometheus/middleware.py", line 57, in dispatch
agiliza-web-1      |     raise e from None
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/starlette_prometheus/middleware.py", line 53, in dispatch
agiliza-web-1      |     response = await call_next(request)
agiliza-web-1      |                ^^^^^^^^^^^^^^^^^^^^^^^^
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/starlette/middleware/base.py", line 165, in call_next
agiliza-web-1      |     raise app_exc
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/starlette/middleware/base.py", line 151, in coro
agiliza-web-1      |     await self.app(scope, receive_or_disconnect, send_no_error)
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/starlette/middleware/authentication.py", line 48, in __call__
agiliza-web-1      |     await self.app(scope, receive, send)
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/starlette/middleware/cors.py", line 83, in __call__
agiliza-web-1      |     await self.app(scope, receive, send)
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/starlette/middleware/exceptions.py", line 62, in __call__
agiliza-web-1      |     await wrap_app_handling_exceptions(self.app, conn)(scope, receive, send)
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/starlette/_exception_handler.py", line 64, in wrapped_app
agiliza-web-1      |     raise exc
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/starlette/_exception_handler.py", line 53, in wrapped_app
agiliza-web-1      |     await app(scope, receive, sender)
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/starlette/routing.py", line 762, in __call__
agiliza-web-1      |     await self.middleware_stack(scope, receive, send)
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/starlette/routing.py", line 782, in app
agiliza-web-1      |     await route.handle(scope, receive, send)
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/starlette/routing.py", line 297, in handle
agiliza-web-1      |     await self.app(scope, receive, send)
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/starlette/routing.py", line 77, in app
agiliza-web-1      |     await wrap_app_handling_exceptions(app, request)(scope, receive, send)
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/starlette/_exception_handler.py", line 64, in wrapped_app
agiliza-web-1      |     raise exc
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/starlette/_exception_handler.py", line 53, in wrapped_app
agiliza-web-1      |     await app(scope, receive, sender)
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/starlette/routing.py", line 72, in app
agiliza-web-1      |     response = await func(request)
agiliza-web-1      |                ^^^^^^^^^^^^^^^^^^^
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/honeybadger/contrib/fastapi.py", line 25, in custom_route_handler
agiliza-web-1      |     honeybadger.notify(exception=exc, context=asgi._as_context(scope))
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/honeybadger/core.py", line 57, in notify
agiliza-web-1      |     return self._send_notice(exception, context=merged_context, fingerprint=fingerprint)
agiliza-web-1      |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/honeybadger/core.py", line 27, in _send_notice
agiliza-web-1      |     return connection.send_notice(self.config, payload)
agiliza-web-1      |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/honeybadger/connection.py", line 16, in send_notice
agiliza-web-1      |     data=b(json.dumps(payload, cls=StringReprJSONEncoder)))
agiliza-web-1      |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
agiliza-web-1      |   File "/usr/local/lib/python3.11/json/__init__.py", line 238, in dumps
agiliza-web-1      |     **kw).encode(obj)
agiliza-web-1      |           ^^^^^^^^^^^
agiliza-web-1      |   File "/usr/local/lib/python3.11/json/encoder.py", line 200, in encode
agiliza-web-1      |     chunks = self.iterencode(o, _one_shot=True)
agiliza-web-1      |              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
agiliza-web-1      |   File "/usr/local/lib/python3.11/json/encoder.py", line 258, in iterencode
agiliza-web-1      |     return _iterencode(o, 0)
agiliza-web-1      |            ^^^^^^^^^^^^^^^^^
agiliza-web-1      | TypeError: keys must be str, int, float, bool or None, not tuple
agiliza-web-1      |
agiliza-web-1      | During handling of the above exception, another exception occurred:
agiliza-web-1      |
agiliza-web-1      | Traceback (most recent call last):
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/uvicorn/protocols/http/httptools_impl.py", line 419, in run_asgi
agiliza-web-1      |     result = await app(  # type: ignore[func-returns-value]
agiliza-web-1      |              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/uvicorn/middleware/proxy_headers.py", line 84, in __call__
agiliza-web-1      |     return await self.app(scope, receive, send)
agiliza-web-1      |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/fastapi/applications.py", line 1054, in __call__
agiliza-web-1      |     await super().__call__(scope, receive, send)
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/starlette/applications.py", line 123, in __call__
agiliza-web-1      |     await self.middleware_stack(scope, receive, send)
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/starlette/middleware/errors.py", line 186, in __call__
agiliza-web-1      |     raise exc
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/starlette/middleware/errors.py", line 164, in __call__
agiliza-web-1      |     await self.app(scope, receive, _send)
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/honeybadger/contrib/asgi.py", line 109, in _run_asgi3
agiliza-web-1      |     return await self._run_app(scope, lambda: self.app(scope, receive, send))
agiliza-web-1      |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/honeybadger/contrib/asgi.py", line 117, in _run_app
agiliza-web-1      |     honeybadger.notify(exception=exc, context=_as_context(scope))
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/honeybadger/core.py", line 57, in notify
agiliza-web-1      |     return self._send_notice(exception, context=merged_context, fingerprint=fingerprint)
agiliza-web-1      |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/honeybadger/core.py", line 27, in _send_notice
agiliza-web-1      |     return connection.send_notice(self.config, payload)
agiliza-web-1      |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
agiliza-web-1      |   File "/usr/local/lib/python3.11/site-packages/honeybadger/connection.py", line 16, in send_notice
agiliza-web-1      |     data=b(json.dumps(payload, cls=StringReprJSONEncoder)))
agiliza-web-1      |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
agiliza-web-1      |   File "/usr/local/lib/python3.11/json/__init__.py", line 238, in dumps
agiliza-web-1      |     **kw).encode(obj)
agiliza-web-1      |           ^^^^^^^^^^^
agiliza-web-1      |   File "/usr/local/lib/python3.11/json/encoder.py", line 200, in encode
agiliza-web-1      |     chunks = self.iterencode(o, _one_shot=True)
agiliza-web-1      |              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
agiliza-web-1      |   File "/usr/local/lib/python3.11/json/encoder.py", line 258, in iterencode
agiliza-web-1      |     return _iterencode(o, 0)
agiliza-web-1      |            ^^^^^^^^^^^^^^^^^
agiliza-web-1      | TypeError: keys must be str, int, float, bool or None, not tuple

I can perfectly reproduce this in my local environment. I have been having a look, but I’m a bit lost at what is happening. I’ve narrowed down the last error and I see that indeed there is a dict with a key which is hard to encode.

What I see is that finally, at encoder.py, line 200 (actually seems to be line 199 for me, at

chunks = self.iterencode(o, _one_shot=True)

I see that it fails if I try self.iterencode(o["request"]["local_variables"]["_"], _one_shot=True)

This ‘_’ key looks like this: image

Why this appears in the local_variables, of course I have no clue.

So, then this raises an exception inside honey badger trying to send the notification to the service, which explains why no error appears in hb itself. If I disable hb, I get the expected 422 response.

In payload.py, line 118: image

I can see that the localvariables do indeed have a `''` variable in it:

image

I have worked around this by disabling local variable collection in honeybadger config in the meanwhile until a fix is found.

joshuap commented 8 months ago

@subzero10 @Kelvin4664 can you take a look at this?

Kelvin4664 commented 8 months ago

Hi @payala I can indeed see from the screenshot that the local variable "_" is a dictionary whose first key is a tuple. I am wondering why it is so in the first place. Can you provide a minimal version of your code to help me reproduce the error? I am trying to confirm the root cause before i work on a patch.

subzero10 commented 8 months ago

Hey @Kelvin4664, it seems that the local variable _ is a function. What if we filter out functions before trying to encode as json?

Hey @payala, while we work out the fix, you may disable local_variables collection through configuration.

Kelvin4664 commented 8 months ago

Hey @subzero10 It goes slightly beyond that. We are correctly encoding the values using a custom encoder to eliminate unserializable values. if you look at the screenshots and traceback closely, you'd notice the problem here is with the dictionary key, not the value. The value of _ looks like this: '_'= {(function, ()): SessionObject}

subzero10 commented 8 months ago

OK, now I get it, thanks @Kelvin4664.

So:

Is the above correct? If yes, what if we traverse the dictionary recursively and apply a transformation to the key if necessary (i.e. change tuple to a string)?

payala commented 8 months ago

Indeed, @Kelvin4664 the problem has to do with the key being a tuple, that's what gives the error. I did have a look to find out why there is this tuple key in the first place, but I didnt find out why or who is injecting this key in there.

The '_' variable is something used in interactive sessions, but in this context it's not obvious to me what this is.

I will try to come up with a minimal version to reproduce the error. For now, I do have the local_variable collection disabled as a workaround.

Thanks for having a look at this guys!

payala commented 8 months ago

OK, bd news, sorry to inform that I'm not able to reproduce it anymore. The endpoint I was using is having a dependency on the "get_db" function.

I'm not sure if this underscore variable is where dependencies are stored through the request processing chain. I had a look at FastAPI code, but I wasn't able to find anything meaningful.

subzero10 commented 7 months ago

Hey @payala, thanks for the update. We will attempt to correct this scenario by either ignoring dictionary keys that are tuples or adding them to the JSON with the key being a string.