natefinch / lumberjack

lumberjack is a log rolling package for Go
MIT License
4.8k stars 591 forks source link

Add Flush() method to Logger #38

Closed smithwinston closed 7 years ago

smithwinston commented 7 years ago

There's no way to flush the log files to disk ... I occasionally noticed that if the go process has been killed or the system rebooted that the log file is incomplete.

Having a Flush() method on Logger that just calls Sync() on the underlying os.File would allow me to run a goroutine that periodically calls Flush() to ensure that the logs are written to disk.

natefinch commented 7 years ago

I'm not sure I see the utility of that. Flushing to disk is something the OS should be in control of. Periodically calling flush is what already happens at the OS level. Yes, the log file could be missing a small amount of logs near reboot time, but that could happen anyway if your goroutine doesn't call flush. The only way to avoid that would be to call sync on every write, and I would expect the performance hit would be unacceptable.

smithwinston commented 7 years ago

@natefinch The problem I've got is that I have a golang program running on an embedded arm-linux board controlling a device via serial. Recently, the device has been hanging up so people are just power cycle it! (no clean shutdowns for me!).

In trying to debug why it hangs up, I set logrus to debug mode, but I don't see the last bit of the log because it hasn't been written to disk. I think part of the issue is that the device is flash based, so it "prefers" to write in larger chunks which means the underlying device/driver is buffering the writes.

While I agree completely with your timing comments, the window in my case is quite large -- many seconds even a minute before the device is restarted by the user.

So in my case, being able to call Sync() on the underlying os.File every 30s or so would solve my problem. I could just fork lumberjack, add this and figure out my issue, but I think it's something I and maybe others would like to have on a permanent basis.

If in the future the Logger instance wraps something other than an os.File, then presumably Sync() would be a no-op.

xiegeo commented 7 years ago

@smithwinston I also develop on a similar system (raspberry-pi 3 for me). My experiences have been the opposite.

The most concerning is that you are getting writes buffered for more than 30 seconds. Do you have any documentation that this is by design on your system? Flash based storage can only do large writes so it does smaller writes by also copying/rewriting adjacent data that did not change, but buffering for a minute to do so does not sound right.

It is possible that there is a buffered writer somewhere in your log stack. It is also possible that your log time stamps can not be trusted. (I had a lot of fun trying to do time related thing on a rpi without a battery backed hardware clock. Without a rtc, you can not trust the absolute time of a log message; with ntp running, you can not trust the relative time between two log messages.)

For me, writes during a power cycle have corrupted both a log file and a git repo once. So I no longer writes any debug logging to permanent storage. My debug logs are only in the memory backed file system, so I can still ssh in to see what is wrong as long as it does not get power cycled.

natefinch commented 7 years ago

As stated above, this does not seem to be something wrong with lumberjack. I don't think it's a good idea to call flush yourself.