Zipping old files blocks all logging for a while

[mrd0ll4r]

Hey! Thanks for writing this library and making it available!

I've run into a problem. I run a project on a raspberry pi, which has a bunch of threads that e.g. poll some attached hardware for changes. For debugging, I log the raw values they get, among other things. All my logs are written to files and everything above warnings is copied to stderr. The problem is this: I set up log rotation, keeping 5 plain-text files and 30 zipped ones. They fill up quite quickly with debug logging on, but that's not surprising. Now, whenever the logs are rotated and an old one is zipped, nothing can log anymore for as long as that takes.

Let me illustrate with a bunch of logs :) This is a fresh start, with no log files, so five plain text files are produced (this doesn't take long), and then later one file is zipped (this takes a while):

Log is written to logs/raspitest_rCURRENT.log
Server is listening on: http://[::1]:3000
[2020-01-29 14:05:40.745225 +00:00] WARN [raspitest::pca9685_sync] src\pca9685_sync.rs:87: took too long, lagging 2918µs behind
[2020-01-29 14:05:40.752097 +00:00] WARN [raspitest::pca9685_sync] src\pca9685_sync.rs:87: took too long, lagging 1558µs behind
[2020-01-29 14:05:40.760958 +00:00] WARN [raspitest::pca9685_sync] src\pca9685_sync.rs:87: took too long, lagging 3750µs behind
[2020-01-29 14:05:40.777664 +00:00] WARN [raspitest::pca9685_sync] src\pca9685_sync.rs:87: took too long, lagging 1387µs behind
[2020-01-29 14:05:40.792007 +00:00] WARN [raspitest::pca9685_sync] src\pca9685_sync.rs:87: took too long, lagging 2462µs behind
[2020-01-29 14:05:40.894974 +00:00] WARN [raspitest::dht22] src\dht22.rs:96: unable to read from pin 26: Checksum
Log is written to logs/raspitest_rCURRENT.log
[2020-01-29 14:05:41.895071 +00:00] WARN [raspitest::pca9685_sync] src\pca9685_sync.rs:87: took too long, lagging 101µs behind
[2020-01-29 14:05:42.988239 +00:00] WARN [raspitest::pca9685_sync] src\pca9685_sync.rs:87: took too long, lagging 7554µs behind
[2020-01-29 14:05:44.185762 +00:00] WARN [raspitest::pca9685_sync] src\pca9685_sync.rs:87: took too long, lagging 406µs behind
[2020-01-29 14:05:44.421706 +00:00] WARN [raspitest::pca9685_sync] src\pca9685_sync.rs:87: took too long, lagging 1663µs behind
Log is written to logs/raspitest_rCURRENT.log
[2020-01-29 14:05:47.943784 +00:00] WARN [raspitest::pca9685_sync] src\pca9685_sync.rs:87: took too long, lagging 215µs behind
Log is written to logs/raspitest_rCURRENT.log
[2020-01-29 14:05:49.726632 +00:00] WARN [raspitest::pca9685_sync] src\pca9685_sync.rs:87: took too long, lagging 259µs behind
[2020-01-29 14:05:49.740501 +00:00] WARN [raspitest::pca9685_sync] src\pca9685_sync.rs:87: took too long, lagging 22µs behind
[2020-01-29 14:05:49.756751 +00:00] WARN [raspitest::pca9685_sync] src\pca9685_sync.rs:87: took too long, lagging 1068µs behind
[2020-01-29 14:05:50.273502 +00:00] WARN [raspitest::mcp23017_input] src\mcp23017_input.rs:131: took too long, lagging 4147µs behind
[2020-01-29 14:05:50.274273 +00:00] WARN [raspitest::pca9685_sync] src\pca9685_sync.rs:87: took too long, lagging 2994µs behind
Log is written to logs/raspitest_rCURRENT.log
[2020-01-29 14:05:52.989480 +00:00] WARN [raspitest::pca9685_sync] src\pca9685_sync.rs:87: took too long, lagging 1677µs behind
[2020-01-29 14:05:55.467321 +00:00] WARN [raspitest::pca9685_sync] src\pca9685_sync.rs:87: took too long, lagging 294µs behind
Log is written to logs/raspitest_rCURRENT.log
[2020-01-29 14:05:57.984365 +00:00] WARN [raspitest::pca9685_sync] src\pca9685_sync.rs:87: took too long, lagging 4783µs behind
Log is written to logs/raspitest_rCURRENT.log
[2020-01-29 14:06:04.791070 +00:00] WARN [raspitest::mcp23017_input] src\mcp23017_input.rs:131: took too long, lagging 4856814µs behind
[2020-01-29 14:06:04.792825 +00:00] WARN [raspitest::pca9685_sync] src\pca9685_sync.rs:87: took too long, lagging 4864683µs behind

I run these things pretty close to their limit, so they're always lagging a bit behind. But note how, after the last rotation, they lag behind a lot. I suspect this is because they tried to debug-log something, but got blocked.

Do you think I got the problem about right?

The obvious solution for me, for now, is to not debug-log (at least in production 😄 ). Long-term: Can we maybe move the zipping to another thread?

Best,

[emabee]

Hi, thanks for the detailed description, and yes, the long-term proposal makes sense, and I think I can look into it soon :-)

[mrd0ll4r]

Thank you! That sounds great :)

[emabee]

Implemented with 0.14.7. For details, see https://docs.rs/flexi_logger/0.14.7/flexi_logger/struct.Logger.html#method.cleanup_in_background_thread

[mrd0ll4r]

Amazing, thank you! :)