TomFrost / Bristol

Insanely configurable logging for Node.js
MIT License
113 stars 19 forks source link

After logrotate creates new file, new log lines fail to write. #15

Closed MartijnR closed 8 years ago

MartijnR commented 8 years ago

I suspect that when logrotate creates a new empty file (with logrotate.conf option create), the writeable stream is gone.

Once the app is restarted, new logs can be written again.

Working around this issue by using logrotate.conf option nocreate has the same problem. The file is not re-created by Bristol.

I don't see any error messages.

TomFrost commented 8 years ago

This is because Bristol gets no notification of the change, and cannot update its file descriptor to point to the newly updated file. It's for the same reason that you have to restart syslogd after logrotate rotates its logfiles, as well. There are two solutions to this problem:

The most convenient option:
Simply specify the copytruncate option in your logrotate config for Bristol's logfile. This causes logrotate to create a new file for the archived version, and then copy the entire contents of the current logfile to the new file. Finally, the active logfile is truncated in place, and Bristol doesn't have to update its file descriptor. The result is zero hiccup in your application with no need to restart. The downside is that, if you log anything in the (albeit very very small) time window between when the copy finishes and the truncate happens, that log message will be lost. Consider this with caution if you utilize high-volume logging and your logs are business-critical; however, with that said, I use this solution in my high-volume applications and have never noticed a dropped log message. The risk window is extraordinarily small.

The safest but more annoying to implement option:
Take the syslog approach and restart the app after rotation. Or, for safety, terminate the app before rotation and start it again once it's complete. If you run multiple instances of your app, you can avoid downtime by scheduling all or a subset of your servers to do this rotation at different times.

MartijnR commented 8 years ago

Thanks a lot for this information. This is really great. I'll use the first option.

cjthompson commented 8 years ago

@TomFrost : Why can't you just use a signal to end and restart the file streams? For example:

process.on('SIGUSR2', reloadLogs);
var file;

function reloadLogs () {
  file.end();
  startLogging();
}

function startLogging()
  file = fs.createWriteStream(errFile, { flags : 'a' });
}
TomFrost commented 8 years ago

Definitely doable -- I wouldn't go so far as to choose the signal on behalf of the user, but a function call in the Bristol api that could be attached to a signal listener (or folder watcher, for that matter) would work. It's important to note that that wouldn't solve everyone's use case, which is why restarting is so common: Consider, for example, running an app inside of a Docker container that logs to a shared volume (common setup for log aggregation tools via Kubernetes/Mesos/ECS/etc). Sending a signal to such a process would be incredibly cumbersome, and in some cases impossible.

But with that said, I'd certainly accept a PR for it, or write it myself if there's enough need!

cjthompson commented 8 years ago

@TomFrost : Here's my first thought on how to do it:

https://github.com/cjthompson/Bristol/commit/c8957c781cef675286c070c9524c7cd36bc81547

It just implements a "restart" function on every target. I'm sure there's a better way to do it but I felt limited by the fact that targets export a single function and that function gets bound. I couldn't think off the top of my head of a better way to send a command other than log to the target.

saifulislam88 commented 1 year ago

Thank you @TomFrost. It is working.