supervisor-stdout introduces some sort of buffer lag, delaying log lines up to ~10 minutes

[whereisaaron]

UPDATE: Fixed by #26 and this fork

I have a supervisor-stdout configuration working well, but the event forwarding is introducing considerable buffer lag into logs. Events collected by supervisor-stdout will often not be emitted by supervisord stdout until up to ~10 minutes later. The time is variable. It is usually worst when applications starts or has been dormant. Logs just don't flow. Then after ~10 minutes a whole bunch of old log messages will be output by supervisord. Once the application gets busy, the lag is usually small or only a few seconds.

You can see here that supervisord output many log lines (~100) in the same micro-second (left timestamp). But the log lines themselves span several minutes (~10 minutes, timestamps on right). This didn't happen until I introduced [supervisor + supervisor-stdout] into the application. Anyone else seen this? Is this a problem with output buffering in the supervisor-stdout handler?

[whereisaaron]

So the problem stems from Python stdout which is automatically block-buffered when not interactive. This used to apply to stderr too, but that no doubt swallowed error messages, so they disabled that. Now the behaviour is inconsistent.

With python 3, there is an extra option to print to flush the buffer, print('foo', flush=True). I patched my branch to do that and it seems to have fixed the huge buffer lag I was seeing.

When interactive, the stdout stream is line-buffered. Otherwise, it is block-buffered like regular text files. The stderr stream is line-buffered in both cases. You can make both streams unbuffered by passing the -u command-line option or setting the PYTHONUNBUFFERED environment variable.

Changed in version 3.9: Non-interactive stderr is now line-buffered instead of fully buffered.

whereisaaron@93ecc0b

[whereisaaron]

I fixed this and made a PR #26.
This fork includes the fix and more formatting features.