Flush log output for info and higher level

[maxberger]

This is required for docker; without flushing, log outputs to stdout are not written immediately, causing confusion (e.g. only errors on startup)

[maxberger]

Note: The failing test is unlelated and fixed in PR #528

[r00t-]

do we really want to do this unconditionally?

[r00t-]

would running with docker -t be a working/acceptable solution?
how do other projects handle this in dockerized services?
it would seem sensible to flush after messages of some minimum log-level, but i.e. not for every debug message.

[maxberger]

Addressed the original comment by adding a config option to enable this conditionally. I never had this problem with other dockerized services, but they usually use an existing log library, which does everything. Only in the case of vzlogger I was not gettting any output until I started adding the flush.

[r00t-]

can you add that parameter to the example vzlogger.conf?

[J-A-U]

I would prefer to not add more (unnecessary?) options to the configuration. Therefore my question:
Is there a reason not to make this behavior standard?

[r00t-]

@J-A-U:
flushing after every message causes unnecessary (disk-)i/o,
specifically when running on a flash filesystem (raspberry pi) one would want to avoid this. (not sure how flush() relates to sync(), but still the buffering is there for a reason.)
i.e. when setting the loglevel to debug, one will want the buffering to avoid extra cpu load.

i suggested the alternative to flush() by default but only for messages of some minimum level. (as in, for errors but not for debug.)
i also asked how other applications handle this. i'm not sure, but i'm pretty sure it's not best-practice to unconditonally flush after every single message.

this whole thing doesn't seem a bg priority to me, as i don't think many people will run vzloger in docker. and systemd doesn't seem to have the same issue, at least it was not reported. (or nobody uses it for logging yet? :\ )

[maxberger]

Here is another post also mentioning the without issue with docker logs, and doing more deep dives:

https://stackoverflow.com/questions/36217674/docker-logs-and-buffered-output (6 years old)

Looks like it is dependent on the docker log driver, so not everyone encounters it.

Flushing for everything >= info would also work, and re-simplify this patch.

I am happy to provide which ever solution you decide on. My goal is to see these messages immediately on my setup, ideally with using upstream. So I can either add update the sample (as requested above), or roll back to flush, but then would use everything >= Info

What would you prefer?

[maxberger]

There is also another option: Use an existing logging library (though that would introduce another dependency, but it would also make the code simpler). I can also prepare a patch for that if you like.

I did a test with python and docker - using "print" statements the log output was delayed, using logger.info statements the output was there immediately. So this issue is not specific to vzlogger or C++

[r00t-]

Here is another post also mentioning the without issue with docker logs, and doing more deep dives:
https://stackoverflow.com/questions/36217674/docker-logs-and-buffered-output (6 years old)

thanks, that's exactly the kind of research i had asked for in #527 (comment)

[r00t-]

@maxberger:
i'd personally accept either:

• the config-option (as in this MR now), with an example in etc/vzlogger.conf that points it out as useful for docker users (nobody will use an option documented only in the sourcecode)
• or flushing depending on loglevel (that was my initial suggestions for improvement)

[maxberger]

Updated. Now flushed only for level input and higher.

[r00t-]

not sure why this is not merged yet,
sorry for the delay and thanks for your contribution.