Fullstack Inertia CSRF token verification failed | Litestar | Page 1

rare mist Nov 30, 2024, 4:34 AM

#

I am following the litestar example and just setup my github oauth APP and set the client id and client secret environment variables.

But when I try to signin to github I get a PermissionDeniedException: 403: CSRF token verification failed

pale pondBOT Nov 30, 2024, 4:34 AM

#

Notes for Fullstack Inertia CSRF token verification failed

At your assistance

@rare mist

No Response?

If no response in a reasonable time, ping @Member.

Closing

To close, type !solve or byte solve.

MCVE

Please include an MCVE so that we can reproduce your issue locally.

rare mist Nov 30, 2024, 4:38 AM

#

And also I did the logfire integration and for some reason I don't see the exceptions being logged there. The successful requests are being logged just fine.

tawny orbit Nov 30, 2024, 6:51 PM

#

rare mist I am following the litestar example and just setup my github oauth APP and set t...

I'll have to recreat this locally. And you only get the csrf error for this login endpoint?

#

does logging in with a local account work fine?

rare mist Nov 30, 2024, 6:53 PM

#

Never mind I did mange to fix it. I had the wrong csrf_cookie_name set for some reason.

I still wonder why the exception did not show up in logfire though. Any ideas?

#

@tawny orbit I managed to fix the exception not showing in logfire as well. It shows up now.

But it doesn't have the full information. It looks more like it was logged as an uncaught exception with no additional context.
The console log has a proper stacktrace and everything.

{4 items
"connection_type": "http"
,
"logfire.disable_console_log": true
,
"logfire.msg_template": "Uncaught exception"
,
"path": "/register/github"
,
}

Would this have something to do with the otel middleware ordering and stuff like that?

tawny orbit Nov 30, 2024, 7:14 PM

#

yeah, it's one of the things i need to figure out. It's either this, or the bigger thing that i was looking to address

#

OTEL is not aware of any of the "non-asgi" bits of litestar

#

so, we need to instrument them

#

meaning, the CLI, channels, events, (maybe) the. top level expection handlers, etc

#

I don't think this is a big of a lift as it sounds once we figure out how it's done.

#

but this will make the opentelemetry experience much better overall

#

as things will always be grouped within the spans correctly

#

Last thing on this, we can easily test to see if it's a logfire vs otel issue by using signoz locally

#

from what i can tell, logfire doesn't add any additional data to existing otel spans

rare mist Nov 30, 2024, 7:18 PM

#

I thought it maybe related to this?

        if as_json:
            return [
                structlog.contextvars.merge_contextvars,
                structlog.processors.add_log_level,
                structlog.processors.format_exc_info,
                structlog.processors.TimeStamper(fmt="iso"),
                structlog.processors.JSONRenderer(serializer=json_serializer),
            ]
        return [
            structlog.contextvars.merge_contextvars,
            structlog.processors.add_log_level,
            structlog.processors.TimeStamper(fmt="iso"),
            structlog.dev.ConsoleRenderer(
                colors=True, exception_formatter=RichTracebackFormatter(max_frames=1, show_locals=False, width=80)
            ),
        ]

It seems like logfire might not be able to see the backtrace if we are using the ConsoleRenderer?

tawny orbit Nov 30, 2024, 7:18 PM

#

Perhaps, this can be easily tested though if you just hardcode tty to True

#

but i don't think this is the case

#

i use OTEL quite often with this config

#

(just not with logfire)

#

in fact, this lets those otel parsers get structured logging output

rare mist Nov 30, 2024, 7:20 PM

#

Cool, I am actually not tied to logfire, just testing because that's what I found in your examples. It's not free or open source either. Is signoz any good?

tawny orbit Nov 30, 2024, 7:20 PM

#

signoz is not bad. It's just vanilla otel

#

you can use what's in inertia and just remove logfire totally but keep the other otel bits

#

Also, I think we can move that middleware singleton thing into litestar main now

rare mist Nov 30, 2024, 7:23 PM

#

I just forced as_json and this is what I get now

{
  "connection_type": "http",
  "exception": "[Scrubbed due to 'auth']",
  "logfire.disable_console_log": true,
  "logfire.msg_template": "Uncaught exception",
  "logfire.scrubbed": [
    {
      "path": [
        "attributes",
        "exception"
      ],
      "matched_substring": "auth"
    }
  ],
  "path": "/register/github"
}

Still no backtrace, but maybe it's because of the scrubbing. But when you tested with other backends, were you also not able to get the stracktrace. So it's not really specific to logfire?

tawny orbit Nov 30, 2024, 7:26 PM

#

rare mist I just forced as_json and this is what I get now ``` { "connection_type": "ht...

maybe i didn't notice the scrubbing piece here.

#

I feel like i do get stack traces in google cloud. I basically use the open source instrumentation and just collect with GCP. Signoz is the exact same as this GCP method but has a local viewer

#

so you'd get the exact same data

#

I'll have to verify that to be certain though

#

you can easily test this by just removing logfire

#

and triggering the exception

rare mist Nov 30, 2024, 7:27 PM

#

But still the exception field is completely missing when not using as_json which relies on the tty check. So it could be tied to that as well.

I do see the excetpion stacktrace in my console irrespective of anything. It's just not showing up in logfire though

tawny orbit Nov 30, 2024, 7:28 PM

#

I'll also go through my structlog setup. I think it may be different (not significantly) than what's in inertia

#

https://github.com/litestar-org/litestar-fullstack-inertia/blob/main/app/lib/otel.py#L53

late tangleBOT Nov 30, 2024, 7:28 PM

#

app/lib/otel.py line 53

logfire.configure()

tawny orbit Nov 30, 2024, 7:28 PM

#

if you remove this

#

and this: https://github.com/litestar-org/litestar-fullstack-inertia/blob/main/app/server/core.py#L91

late tangleBOT Nov 30, 2024, 7:29 PM

#

app/server/core.py line 91

logfire.configure()

tawny orbit Nov 30, 2024, 7:29 PM

#

there's no change, right?

#

other than the logfire fields are missing and no "scrub"

rare mist Nov 30, 2024, 7:30 PM

#

I figured out a way to disable the scrubbing and I do get this now

{
  "connection_type": "http",
  "exception": "Traceback (most recent call last):\n  File \"/home/void/Projects/Python/chatpyre/.venv/lib/python3.12/site-packages/litestar/middleware/_internal/exceptions/middleware.py\", line 159, in __call__\n    await self.app(scope, receive, capture_response_started)\n  File \"/home/void/Projects/Python/chatpyre/.venv/lib/python3.12/site-packages/litestar/middleware/authentication.py\", line 90, in __call__\n    await self.app(scope, receive, send)\n  File \"/home/void/Projects/Python/chatpyre/chatpyre/lib/log.py\", line 83, in middleware\n    await app(scope, receive, send)\n  File \"/home/void/Projects/Python/chatpyre/.venv/lib/python3.12/site-packages/litestar/middleware/base.py\", line 129, in wrapped_call\n    await original__call__(self, scope, receive, send)  # pyright: ignore\n    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n  File \"/home/void/Projects/Python/chatpyre/.venv/lib/python3.12/site-packages/litestar_vite/inertia/middleware.py\", line 52, in __call__\n    await self.app(scope, receive, send)\n  File \"/home/void/Projects/Python/chatpyre/.venv/lib/python3.12/site-packages/litestar/middleware/csrf.py\", line 133, in __call__\n    raise PermissionDeniedException(\"CSRF token verification failed\")\nlitestar.exceptions.http_exceptions.PermissionDeniedException: 403: CSRF token verification failed",
  "logfire.disable_console_log": true,
  "logfire.msg_template": "Uncaught exception",
  "path": "/register/github"
}

tawny orbit Nov 30, 2024, 7:31 PM

#

is the scrubbing a logfire thing?

#

(i'm guessing)

rare mist Nov 30, 2024, 7:31 PM

#

Yep

Which means whether or not I get the exception seems tied to the is_tty check and the default processors

tawny orbit Nov 30, 2024, 7:32 PM

#

rare mist Yep Which means whether or not I get the exception seems tied to the is_tty che...

ok, I may have left off a processor that i have

rare mist Nov 30, 2024, 7:33 PM

#

If I disable scrubbing and remove the force as_json

I only get 4 fields

{
  "connection_type": "http",
  "logfire.disable_console_log": true,
  "logfire.msg_template": "Uncaught exception",
  "path": "/register/github"
}

Is it maybe the structlog.processors.format_exc_info? That seems to be the only relevant one that's missing.

tawny orbit Nov 30, 2024, 7:34 PM

#

yeah, I'll need to go through the structlog documentation. If you figure it out and want to make a PR (or drop details here), go for it.

#

i think I'll disable logfire by default as well

#

or have it separate from OTEL

#

i just thought it might be helpful to show how it integrates given pydantic's popularity

#

I don't actively use it though

rare mist Nov 30, 2024, 7:36 PM

#

Yep. I Just checked if I add structlog.processors.format_exc_info the exception shows up in logfire.

But it overrides the Rich formatting in the console as well. Don't know how to get both working together

tawny orbit Nov 30, 2024, 7:38 PM

#

it might be worth disabling the custom logging middleware i added in inertia as well

#

i'm starting to wonder if this might have something to it as well

#

there's a custom logging backend that logs a single log entry for the request and response instead of 2 logs like the default

rare mist Nov 30, 2024, 7:43 PM

#

Nope I tried that I don't think it's related.

I think adding the structlog.processors.format_exc_info stops the ConsoleRenderer formatter from working or overrides it somehow.

But having it seems to be the only way to get logfire to have the exception.

            structlog.contextvars.merge_contextvars,
            structlog.processors.add_log_level,
            structlog.processors.format_exc_info,
            structlog.processors.TimeStamper(fmt="iso"),
            structlog.dev.ConsoleRenderer(
                colors=True, exception_formatter=RichTracebackFormatter(max_frames=1, show_locals=False, width=80)
            ),

tawny orbit Nov 30, 2024, 7:44 PM

#

interesting. i'll give this a test shortly as well

#

thanks for debugging this one

rare mist Nov 30, 2024, 7:47 PM

#

Well for what it's worth ChatGPT seems to suggest that

To achieve both Rich formatting in the console and exceptions in Logfire, even when running in a TTY, you can use two separate loggers or outputs—one for console (TTY) and another for Logfire (JSON). Structlog supports this by allowing you to attach multiple outputs to the logging pipeline.

But that just sounds too complex

tawny orbit Nov 30, 2024, 7:48 PM

#

rare mist Well for what it's worth ChatGPT seems to suggest that ``` To achieve both Rich...

This is actually how it works now

#

it's based on the tty hook

#

when no tty, it configures the json handlers

#

is it suggesting to use 2 loggers in tty...

#

i see

rare mist Nov 30, 2024, 7:51 PM

#

Currently litestar seems to be one or the other. I am running in a tty, so it does not have the structlog.processors.format_exc_info

And uses the ConsoleRenderer.

But not having structlog.processors.format_exc_info causes the exception to not show up in logfire. But the console is rich formatted.

If I manually add the structlog.processors.format_exc_info even when running in a TTY. I get the exceptions in logfire, but not the console formatting.

Seems like I am having to chose between one or the other.

I think ChatGPT seems to think this can be solved by using two different loggers in tty if I want both

tawny orbit Nov 30, 2024, 7:52 PM

#

rare mist Currently litestar seems to be one or the other. I am running in a tty, so it do...

structlog is awesome, but can get really complicated

#

let me think about this a bit too see if there's a better way

rare mist Nov 30, 2024, 11:58 PM

#

Yeah I think it's definitely logfire

This is their call method for the StructlogProcessor

    def __call__(self, logger: WrappedLogger, name: str, event_dict: EventDict) -> EventDict:
        """A middleware to process structlog event, and send it to **Logfire**."""
        attributes = {k: v for k, v in event_dict.items() if k not in RESERVED_ATTRS}
        level = event_dict.get('level', 'info').lower()
        if level == 'error':
            print('LOGGING_RESERVED_ATTRS', RESERVED_ATTRS, flush=True)
            print('EVENT_DICT', event_dict, flush=True)
            print('LOGFIRE ATTRS EXCEPT', attributes, flush=True)
        # NOTE: An event can be `None` in structlog. We may want to create a default msg in those cases.
        attributes[ATTRIBUTES_MESSAGE_KEY] = message = event_dict.get('event') or 'structlog event'
        self.logfire_instance.log(
            level=level,  # type: ignore
            msg_template=message,
            attributes=attributes,
            console_log=self.console_log,
        )
        return event_dict

You can see what's being printed when I don't have the format_exc_info

LOGGING_RESERVED_ATTRS frozenset({'thread', 'message', 'args', 'taskName', 'event', 'level', 'filename', 'lineno', 'name', 'pathname', 'asctime', 'exc_info', 'timestamp', 'stack_info', 'exc_text', 'process', 'levelname', 'levelno', 'relativeCreated', 'created', 'msg', 'processName', 'funcName', 'threadName', 'module', 'msecs'})
EVENT_DICT {'connection_type': 'http', 'path': '/register/github', 'exc_info': True, 'event': 'Uncaught exception', 'level': 'error', 'timestamp': '2024-11-30T23:44:35.526083Z'}
LOGFIRE ATTRS EXCEPT {'connection_type': 'http', 'path': '/register/github'}

They don't seem to have any special handling of exceptions, they just show it if the exception field is there. Which gets added by format_exc_info. But having that field messes up the RichFormatter I think.

#

There is definitely a way to solve this with the right order and combination of processors I think, now that I know this.

rare mist Dec 2, 2024, 3:10 AM

#

@tawny orbit this is definitely a Logfire issue. They are not making use of the exc_info field set by Structlog

Take a look at the issue I filed.

https://github.com/pydantic/logfire/issues/636#issuecomment-2510464135

#Fullstack Inertia CSRF token verification failed