chore: adding a logger masking filter

[staaldraad]

What kind of change does this PR introduce?

Bug fix / feature

What is the current behavior?

INFO log lines may contain the access_token jwt

What is the new behavior?

Use a logging.Filter to redact JWT tokens that may be in log messages.
JWT's will be displayed as eyJh.REDACTED.2j7_78f where eyJh would be the full header and 2j7_78f would be the full signature.

$ python3 app.py                                                                                                                                                                                                                                                                                                                
2024-10-01 12:44:53,590:INFO - Connection was successful
2024-10-01 12:44:53,777:INFO - Connection was successful
2024-10-01 12:44:53,778:INFO - send: {"topic": "realtime:test-broadcast", "event": "phx_join", "payload": {"config": {"broadcast": {"self": true}, "presence": {"key": ""}, "private": false, "postgres_changes": []}, "access_token": "eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.REDACTED.2j7_78fvwrR3Ok3zTWOrPmS4HgvAY8xWpMdTM7MX-bg"}, "ref": "1", "join_ref": "1"}
2024-10-01 12:44:54,780:INFO - send: {"topic": "realtime:test-broadcast", "event": "broadcast", "payload": {"type": "broadcast", "event": "test-event", "payload": {"message": "Event 1"}}, "ref": "2", "join_ref": "1"}
2024-10-01 12:44:54,781:INFO - send: {"topic": "realtime:test-broadcast", "event": "broadcast", "payload": {"type": "broadcast", "event": "test-event", "payload": {"message": "Event 2"}}, "ref": "3", "join_ref": "1"}

Additional context

Doesn't address the fact that logging set to DEBUG will have the JWT in the connection log line created by websockets.
Websocket DEBUG logs are also redacted after adding 053221b

[etzelc]

Hi @staaldraad,
I suggest modifying the regex to match all characters allowed in a JWT according to their Base64url-Encoding specification (see RFC7515 - 2. Terminology: Base64url-Encoding https://datatracker.ietf.org/doc/html/rfc7515#section-2 ). This adds _ and -.

redact = r"(eyJ[A-Za-z0-9_-]*\.)([A-Za-z0-9_-]*)\."

Since the pattern is static, it might also be beneficial to precompile it.

[etzelc]

For the DEBUG logs from websockets, it might be possible to apply the filter to the websocket logger as well. (untested)

websockets_logger = logging.getLogger('websockets')
websockets_logger.addFilter(TokenMaskingFilter())

[staaldraad]

For the DEBUG logs from websockets, it might be possible to apply the filter to the websocket logger as well. (untested)

websockets_logger = logging.getLogger('websockets')
websockets_logger.addFilter(TokenMaskingFilter())

Unfortunately it doesn't work in the current form because the websockets logging is coming in as logging.debug("%s : %s", args). So the filtering needs to be on record.args and not record.msg (msg is the "%s : %s"). However, when trying to filter records.args it ended up changing the values in the tuple, breaking websockets. I was probably doing something wrong, but I should also really be handing this to better devs than myself 😅

[o-santi]

I know I'm late to this, but I do not like the approach of this PR. Not only it forces every argument to every logger to be deep copied (which is not cheap), but it also applies a regex to any and all arguments, regardless of whether or not they may contain a JWT, which does raise some performance considerations. In realtime-py, most messages won't contain JWTs so it is simple to in-place patch places that may log these tokens, without the need for a catchall solution.

Furthermore, I'd like to understand more the threat model behind this reasoning. Any python client that sees these logs should already have unrestricted access to the access_token, as python does not properly implement private methods in clients, so there should be a path to directly reading it, even if it's through a 3rd party library. What are we avoiding then?

Either way, I'm not against this change per se, as logging access tokens does not seem like a great idea, but I'll close this specific PR in favor of better approaches that are a little more specific and have lesser performance considerations.

[etzelc]

Hi @o-santi. I initially reported this through HackerOne because this was the issue we were facing:

In a Kubernetes cluster with centralized logging and monitoring, logs containing sensitive information like the service_role key can become a critical attack vector. If an attacker gains access to the centralized logging system or if personnel, who are only authorized to monitor the system but not have access to the Supabase instance, have access—these tokens could be exposed.

As another example, I also linked in the HackerOne report a public GitHub issue, which disclosed a service_role key of an active SaaS Supabase instance in the logs associated with the issue.

There also exists a Common Weakness Enumeration for this type of issue: CWE-532: Insertion of Sensitive Information into Log File

I do not have a concrete solution in mind for how to fix it, but I strongly believe it should be addressed.