forever: Logrotation on output log file causes empty log files

Having done server maintenance for several years, this is a common issue that is not specific to forever. I understand what’s going to be this:

While you appear to be logging to a file, you are really logging to a file descriptor. After log rotation by an external application, the application continues to log to a file descriptor, but now it is no longer connected with the file, which has been re-created through log rotation. While the log may be empty, your disk space may well be continuing to increase.

Possible solutions to log rotation complications

logrotate and copytruncate

Above there was a recommendation to use logrotate and the copytruncate options. This is designed to workaround the file-descriptor-vs-file issue described above by leaving the relationship intact. Instead of renaming the file, it’s first copied to the rotated location and then truncated back to an empty state, as opposed to renaming the file. This works, but feels like a workaround.

Restart the app

logrotate and similar solutions can help you send a command to restart the app during log rotation so that filename-vs-file-descriptor relationship gets refreshed. This works too. If like me, you are also on-call to respond to problems with apps restarting at midnight, you would probably prefer to find another solution that doesn’t mess with your application in the middle of the night. (What could go wrong with simply restarting an app in the middle of the night?)

Build log rotation into forever

You could submit a pull request which adds log rotation into forever, but this is a general problem. Does it make sense for every single server or process supervisor to roll-its-own log rotation solution? Surely there’s a more general solution to this.

Log directly from your app over the network to syslog or a 3rd-party service.

This avoids the direct use of log files, but most of the options I’ve looked for this in Node.js share the same design flaw: They don’t (or didn’t recently) handle the “sad path” of the remote logging server being unavailable. If they coped with it at all, the solution was to put buffered records into an in-memory queue of unlimited size. Given enough logging or a long enough outage, memory would eventually fill up and things would crash. Limiting the buffer queue size would address that issue, but it illustrates a point: designing robust network services is hard. Your are likely busy building and maintaining your main application. Do you want to also be responsible for the memory, latency and CPU concerns of a network logging client embedded in your application?

For reference, here are the related bug reports I’ve opened about this issue:

• in node-bunyan-syslog lack of queue size management could lead to memory exhaustion, crash. #24
• in logentries-stream If Logentries connection fails, unbounded memory growth occurs, causing potential crash and loss of logs #1 reported to be fixed
• in winston-logentries-simple Logs lost if LogEntries is unreachable. #2 author responded that “I used this in a project where losing logs was OK”
• in logentries-client Bad DNS or Bad API tokens cause silent failure, infinite queue growth #4 reported fix.

If you are using this a module that logs over the network directly, you might wish to check how it handles the possibility that the network or logging service is down.

Log to STDOUT and STDERR, use syslog

If your application simply logs to STDOUT and STDERR instead of a log file, then you’ve eliminated the problematic direct-use of logging files and created a foundation for something that specializes in logging to handle the logs.

I recommend reading the post Logs are Streams, Not Files which makes a good case for why you should log to STDOUT and shows how you can use pipe to logs to rsyslog (or another syslog server) from there, which specialize in being good at logging. They can do things like forward your logs to a third party service like LogEntries, and handle potential networks issues there outside your application.

Logging to STDOUT and STDERR is also considered a best practice in the App Container Spec. I expect to see more of this logging pattern as containerization catches on.

There are also good arguments out there for logging as JSON, but I won’t detour into that now.

Log to STDOUT, use systemd

systemd can do process-supervision (like forever), including user-owned services, not just root. It’s also designed to handle logging that services send to STDOUT and STDERR and has a powerful journalctl tool built-in. There’s no requirement that your process supervisor be written in Node.js just because your app is.

Systemd will be standard in future Ubuntu releases and is already standard in Fedora. CoreOs uses Systemd inside its container to handle process supervision and logging, but also because it starts in under a second.

How to Log to STDOUT effectively with forever?

About now, you may be looking at the --fifo option for forever, since it advertises that it sends logs to STDOUT. Pefect! Not quite. Note only is not clear which logs it would send to STDOUT, but it turns out that --fifo is only meant to apply to the logs command, but that’s not clear because the documentation for forever doesn’t tell you which flags go with which options..

What you might hope works:

forever --fifo start ./myapp.js | logger

Besides that --fifo doesn’t work with start currently, there’s also the issue that start causes the app to run in the background, disconnected from forever's STDOUT and STDERR. The issue can be solved by using the bash feature of process substition, like this:

forever -a -l >(logger -t myapp) start ./myapp.js

The >(...) syntax causes bash substitute the command there for a file descriptor that pipes to that command, like a named pipe. When you run forever list, you’ll see an entry in the logfile column that looks like /dev/fd/63. Just like a regular log file, this syntax works even when start runs the app in the background.

You can use the same approach to with the -o and -e flags as well. But output sent to -l already includes the data sent to both the STDOUT and STDERR that would be logged to the -o and -e options. (But maybe it shouldn’t) Also, you would end up with three logger processes running that way.

You are not limited to using this syntax to pipe your logs to logger, you could use the syntax to pipe your logs to anything that is designed to receive logs on STDIN.

You should add “copytruncate” to your config file, that does the job.

/var/log/myfirstforeverscript.log {
    daily
    rotate 10
    missingok
    notifempty
    compress
    sharedscripts
    copytruncate
}

@markstos that is an awesome number of suggestions.

If its so important, provide Pull Request or use alternatives like monit 😃

Why this not be a high-priority problem? We got heavy logs every day. Logrotation is really important to us.