Circular error logging for non-http events in Starlette app

[swenson]

I noticed when upgrading from 0.15.2 to 0.16.1 that our code now hits an infinite loop when we log anything that isn't associated with a request.

It appears that the startlette module tries to populate the request, fails, then logs an error, which tries to populate the request, fails, then logs an error, etc., until it overflow the call stack.

https://github.com/rollbar/pyrollbar/blob/df6a145c1195536e5cb579f48626179df300263c/rollbar/contrib/starlette/requests.py#L52

[omri-shaiko]

I can see this issue as well. If you run this example: https://github.com/rollbar/pyrollbar/blob/master/rollbar/examples/fastapi/app_logger.py

You will see the following error:

ASGI 'lifespan' protocol appears unsupported.

When I run the app with the flag --lifespan on I see the error Request is not available in the present context. multiple times.
This issue breaks fastapi startup event

[indepndnt]

I am also experiencing this in my FastAPI app on the non-request contexts.

I am using this workaround in my logging setup to inject a dummy "request" when in a non-request context.

    if log_context != "api":
        # rollbar 0.16.1 causes a stack overflow by logging "Request is not available in the present context."
        # from the request handler if `get_current_request` has nothing
        from rollbar.contrib.starlette.requests import store_current_request  # noqa

        store_current_request({"type": log_context})

I didn't want to go so far as to clone the repo and make a PR, but if anyone at Rollbar is reading this and would like my suggestions, below is how I would fix it.

---

As far as I can see, the only place rollbar.get_request is used or recommended is in the logging context. I would recommend removing both of the log.error calls in rollbar.contrib.starlette.requests:get_current_request. The first one is a repeat of the warning about aiocontextvars which is logged at the top of the module on import. The second one, my preference would be to simply omit it; however you could instead return something along the lines of {"error": "Request is not available in the present context."} or whatever form of dummy Request/Scope object would get the message back in the Rollbar item.

Probably also worth adding a comment or docstring about not logging from within that function due to the stack overflow issue.

[bxsx]

Thanks @swenson @omri-shaiko @indepndnt for reporting this issue and all the provided details!

I've just opened a pull request #390 that addresses it. A new release with the fix should be released in the coming days.

I would recommend removing both of the log.error calls in rollbar.contrib.starlette.requests:get_current_request. The first one is a repeat of the warning about aiocontextvars which is logged at the top of the module on import.

The first one logs the error in case accessing request objects is not supported. This can happen if contextvars (included in Python 3.7+) or aiocontextvars (a third-party package for Python 3.6) are missing. In this case, there is no value in calling rollbar.contrib.starlette.get_current_request(), so the SDK logs error.

Another log.error about aiocontextvars that is logged at the top of the module is not redundant as it can be only reported in Python 3.6 when the third-party package is missing. So it contains more useful information for Python3.6 users that want to take advantage of this feature and missed the installation of the required aiocontextvars package.

The second one, my preference would be to simply omit it; however, you could instead return something along the lines of {"error": "Request is not available in the present context."} or whatever form of dummy Request/Scope object would get the message back in the Rollbar item.

This log.error is dropped in #390. The function returns None if there is no request object for the local context and no longer logs the error.

Probably also worth adding a comment or docstring about not logging from within that function due to the stack overflow issue.

I imagine the stack overflow problem was due to incorrect redundant error logging in case of missing context. In other cases, it should be safe to use logging when needed. However, if you encounter any other issues (after applying #390), please report them so we can take further action.

[bxsx]

@swenson @omri-shaiko @indepndnt Happy to announce a new release of the SDK that addresses this issue. Please upgrade to SDK to the most recent version (v0.16.2 at the moment) and let me know if you still occur any issues here. Thanks!

[indepndnt]

Thanks @bxsx !