byte strings with utf8 in them can cause logger to recurse and explode

[ara4n]

As per #3470.

Whilst I've fixed that particular cause, it feels disasterous that if we pass a byte-string as a parameter to the logger which includes a utf8 sequence, the logger explodes, recursing and taking out the whole app, typically with a massive memory leak whilst stuck in a pyflame that looks like:

https://matrix.org/_matrix/media/v1/download/matrix.org/AHBHDDaOVTayKiibbmnHSKqO.

This caused multiple production outages over the last 2 weeks due to someone deciding to unexpectedly hand us a utf8 User-Agent :|

[richvdh]

For added confusion, the logcontext on the error is misleading, because the error occurs when the log message is formatted, which happens in batches and can happen when processing any request.

[richvdh]

the failure mode here is specifically attempting to write a log line with a mix of unicode and str (aka bytes) params:

logger.info("%s %s", u"foo", b"\xe2")

the presence of the unicode param means that the str params will be decoded with the default (ascii) codec, which then fails.

The proximal solution here is of course to make sure that everything that goes to a logger is already decoded to a unicode string, which the python 3 work will help with anyway.

The reason it then causes stack overflows and OOMs is thanks to an interaction of the stdlib memoryhandler and the fact that we redirect stderr to the logs. MemoryHandler basically goes:

if len(buffer) >= cap:
    for record in buffer:
        log_to_disk(record)
    buffer = []

If the log_to_disk throws an exception, that is caught and written to stderr, which goes through the redirection, so adds another log record to the MemoryHandler's buffer, and runs the code above again.

We should do one of:

• Not redirect stderr to the logs (and instead fix stderr goes to /dev/null when we run with --daemonize #1539)
• Use something other than MemoryHandler and make logging properly asynchronous
• Ensure that the redirected stderr does not go via MemoryHandler. One way to do this would be to configure the twisted stdlib logger to go direct to the StreamHandler rather than going via the MemoryHandler.

[richvdh]

we've now worked around this with option 3 (configure the twisted stdlib logger to go direct to the StreamHandler). I still think it's a bit rubbish that we're redirecting stderr to the logs, but I guess that's a separate problem.

[richvdh]

This is now fixed a bit better with #8268. We could potentially remove the special-case for the twisted logger.

[richvdh]

This is now fixed a bit better with #8268. We could potentially remove the special-case for the twisted logger.

done in #12589