stderr goes to /dev/null when we run with --daemonize

[matrixbot]

Submitted by @​matthew:matrix.org
just wasted 30 minutes because an uncaught exception sent to stderr was being swallowed by synctl >:(

(Imported from https://matrix.org/jira/browse/SYN-686)

[richvdh]

The problem here is not so much that synctl uses --daemonize, but that there is no way to get hold of stderr with --daemonize. (By default, it is directed through the python logger, but that leads to hellish loops like #3471, makes doing things like #3402 hard, and means that error messages from the C subsystem get completely lost).

I think the ideal here is:

• We change the default log config to not spam all the logs to the console (done in Change the default log config to reduce disk I/O and storage #8040).
• We probably stop using daemonize, because it will re-redirect stdout and stderr to /dev/null. It's only about 200LOC, and we only use about 50% of them anyway. (done in re-implement daemonize #8011)
• We add a new config param/cmdline arg which specifies a file that stdout and stderr should be redirected to. It will need a sensible default, which is different from homeserver.log. (It should probably not be called log_file/--log-file/-f, to avoid the risk that people are setting those things to homeserver.log and have a log_config which does the same thing)
• If --daemonize is specified, we redirect stdout and stderr [1] to that file on startup. If it is not specified, we leave them where they are. This needs to happen very early - preferably before we set up the python logs, so that if the python logs are configured to go to stderr, they all end up in the file rather than split between console and file.
• We make sure we write a timestamped "STARTING" marker to the file.
• During the startup sequence, until we fork, we write some diagnostic messages to the original stdout (for example: Synapse now listening on port NNNN). These will replace the stuff that is currently spat out from synctl, via the console logger.
• We reopen the file on SIGHUP, to allow it to be logrotated (note that this will mean recording the abspath at startup, since we chdir after startup). A timestamped marker would be useful.
• We ignore the --no-redirect-stdio flag (and write a warning), since it is redundant.

This then allows the following configurations:

• Those using synctl with a stock config will get most of their logs going to homeserver.log (with free log rotation), with anything that misses the net going to homeserver.out or whatever (with no logrotation, but hopefully it will be sufficiently low volume this won't be a problem).
• People using systemd can run without --daemonize (and should set Type=simple in the systemd config); again most of their logs will go to homeserver.log; other stuff will go to journald.
• Those who prefer not to have a separate homeserver.log can instead configure log_config.yaml to write to the console. They will have to manage their own logrotation (either via logrotate or let journald sort it out).

I see one particular fly in this ointment:

• The default log_config used to be for all the logs to go to the logfile and to sys.stderr. Historically, that didn't really matter hasn't really mattered, because sys.stderr ended up pointed at /dev/null; however if we fix that, people using the old default config will end up with all their logs going to two files, one of which won't have any buffering or logrotation. It might be worth trying to detect the situation where the root logger is configured to go to both a filehandler and a StreamHandler; we can then warn about it and attempt to fix it.

[1] redirecting the real stdout and stderr looks like:

import os

original_stdout  = os.dup(1)

with open('file', 'w+') as f:
    os.dup2(f.fileno(), 2)
    os.dup2(f.fileno(), 1)