Logrotation on output log file causes empty log files #106

Open
giggsey opened this Issue Aug 24, 2011 · 47 comments

Projects

None yet
@giggsey
giggsey commented Aug 24, 2011

My logrotate.d script:

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

forever runs in daemon mode.

forever start -a -l /var/log/myfirstforeverscript.log -c node --pidfile /var/run/myfirstforeverscript.pid /myfirstforeverscript.js

After logrotate runs overnight, it copies sends it off to the file fine, but forever then doesn't continue writing to the main log file.

It's most likely something up with my logrotate.d script, but any ideas?

@jeffchan

👍

@AvianFlu
Contributor

Was this issue ever resolved? has it persisted on more recent versions of forever?

@segmentio-prod

@giggsey, does this still happen or is it resolved?

@giggsey
giggsey commented Dec 5, 2011

Haven't updated and tested for a while.
On Dec 5, 2011 8:17 PM, "segmentio-prod" <
reply@reply.github.com>
wrote:

@giggsey, does this still happen or is it resolved?


Reply to this email directly or view it on GitHub:
#106 (comment)

@leric
leric commented Sep 19, 2012

Some daemon services like nginx answer to a signal like SIGUSR1 to reopen the log file, so we can use 'postrotate' in logrotate config file to do log rotating:
/opt/nginx/logs/access.log {
......
postrotate
/bin/kill -USR1 /bin/cat /opt/nginx/logs/nginx.pid
endscript
}

Maybe forever can have a similar implementation

@mnesales

I'm using forever with node v0.8.8 and I still cannot logrotate the forever logs without completely restarting the forever process. My vote is to include a logrotation feature within forever.

@bard
bard commented Oct 21, 2012

I would have expected to be able to do this to manually rotate logs (process 0 logs to ~/.forever/foo.log):

mv ~/.forever/foo.log ~/.forever/foo.log.0
forever restart 0

Instead forever kept logging to foo.log.0, I suppose because it doesn't close then reopen log files on forever restart, so it keeps writing to the same file inode regardless of renames.

It's not optimal, but forever stop 0 then forever start <process> did the trick.

@sebastianhoitz

I just opened a pull request, that makes it possible to use logrotate with forever:

foreverjs/forever-monitor#16

Feel free to leave any feedback :)

@jdponomarev

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

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

I have copytruncate and I'm still seeing this issue with forever@0.10.0, node@v0.8.14 and this in my logrotate.d directory

/home/ec2-user/.forever/cloud.log {
daily # how often to rotate
rotate 100 # max num of log files to keep
missingok # don't panic if the log file doesn't exist
notifempty # ignore empty files
compress # compress rotated log file with gzip
sharedscripts # no idea what it does, but it's in all examples
copytruncate # needed for forever to work properly
dateext # adds date to filename
dateformat %Y-%m-%d.
}

all the forever logging moved to a file called cloud.log-20130704 (the first day it rotated) and each day a new empty file is created. cloud.log(the original) is zero. And of course a forever restart doesn't fix it - logging continues to the same file.

Any fixes or am I switching to another logging / daemon framework?

@chovy
chovy commented Nov 13, 2013

I'm still having this problem.

@reklis
reklis commented Jan 14, 2014

Issue effecting me as well. I'll submit a patch if somebody can point me to the right place in the code to fix it.

@0x80
0x80 commented Jan 28, 2014

+1!

@llaakso
llaakso commented Mar 6, 2014

Is there any workaround?

@domwoe
domwoe commented Mar 26, 2014

+1!

@triccardi-systran

The feature is still needed and still useful (it's hard to bypass this: logrotate "copytruncate" is not perfect, replacing logrotate by something else is not viable for standard deployments, and restarting the server is not wanted in many cases).

The foreverjs/forever-monitor#16 PR is outdated, and the re opening of the fd were not atomic. With the current master it seems easier to do since we don't touch the child process fd directly, just read from them and pipe the data to a (file) stream.

@ronny332

+1!

@lukedemi

+1!

@jonkafton

+1

@hansgill

+1

@kosch
kosch commented Aug 21, 2014

+1

@1999
1999 commented Aug 26, 2014

We plan to move to recluster, which allows graceful restart & probably has a fix for this problem.

@triccardi-systran

The reload() in the link from @jfroffice is probably invalid because it ignores the fd returned by fs.openSync. However, using sync versions of close & open is one way to correctly implement an atomic reload. (another non-blocking way would maybe be to async open, then async close, and on the close callback set the newly open fd where it's used. I'm not sure it works...)

Also, writing to process.stdout seems to be blocking (see http://nodejs.org/api/process.html#process_process_stdout), so it may not be a good idea for the logs.

@iq-dot
iq-dot commented Oct 28, 2014

What are people doing here on production? Are they just turning of the logs? We have winston logs with logrotation but can't seem to figure out what to do with forever.

@indexzero indexzero removed the low-priority label Oct 30, 2014
@Yinear
Yinear commented Nov 5, 2014

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

@kosch
kosch commented Nov 5, 2014

If its so important, provide Pull Request or use alternatives like monit :-)

@lklepner

+1

@fiosca
fiosca commented Nov 17, 2014

+1

@Grynn
Grynn commented Dec 28, 2014

+1

@jamesongithub

+1

@2naive
2naive commented Jan 18, 2015

@indexzero @mmalecki so could you please comment this topic? I suppose it's one of the most valueable problems.

@indexzero
Member

Is there a script I can run to debug this quickly?

@2naive
2naive commented Jan 23, 2015

You mean like:

setTimeout(function() {console.log(new Date().toString() );}, 1000);

or I misunderstood the question?

@2naive
2naive commented Jan 26, 2015

So, in case of create logrotate option - forever proceeds to write to rotated log file instead of main one.
If copytruncate option set - forever write to main log file, but it's not wiped when rotated and logs keep accumulate.

Does someone have a solution?

@sheldonh

Could a maintainer clarify whether this isn't understood to be a problem? The forever command-line utility seems to be useless to us in production, because we can't safely rotate its logs, and so have to resort to programmatic use of forever-monitor, so that we can configure the logging. But this issue has been open so long, perhaps I've misunderstood something that makes it a non-problem?

@lklepner

I've been forced to move away from Forever in production due to this.

@indexzero
Member

@sheldonh @lklepner it's a problem. No one has provided a usable script to reproduce this end-to-end so can't debug it. If you could do that then we'd be happy to fix it.

By end-to-end this example should assume forever is installed and then:

  1. Include a node.js script that forever runs.
  2. Setup, install, and/or confirm the existence of whatever log rotation utilities being used.
  3. Include exact configuration files for said log rotation utility.
  4. Include the exact forever command being run.
  5. (ideally) Be able to reproduce the bug in under 1 minute.
@lasar
lasar commented Apr 14, 2015

I have created a small test setup here: https://github.com/lasar/forever-106
The readme file contains all steps to reproduce.

I don't have any log rotation setup handy but the problem exists even when just using mv to move the log file.

@indexzero
Member

Thank you @lasar. I am in the last thralls of organizing EmpireJS, but I have escalated this on my OSS todo list and will look at it after the event.

@markstos
markstos commented Jun 30, 2015 edited

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:

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.

@reklis
reklis commented Jun 30, 2015

+1 for "log to stdout and use systemd"

@indexzero
Member

@markstos that is an awesome number of suggestions.

@markstos

Thanks for the feedback, @indexzero

@mbland mbland added a commit to 18F/pages that referenced this issue Oct 1, 2015
@mbland mbland Fix logrotate issue with logs going to wrong file
Noticed that there was a new `/var/log/18f-pages-server/pages.log` file, but
that the logs were still going to an uncompressed
`/var/log/18f-pages-server/pages.log.1`. The old `postrotate` script wasn't
actually successfully restarting the server, and a manual restart also didn't
allow the new process to write to the new log file.

Found out about the `copytruncate` directive, which will work well enough for
18F Pages, though it's not completely ideal. For more information, this issue
has a very helpful comment with a ton of technical background:

foreverjs/forever#106 (comment)
c14fc9e
@devinivy

@markstos that is a brilliant suggestion– using process substitution. Thanks!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment