Rippled: logrotate command does not close log

[crypticrabbit]

Issuing logrotate has no impact on my debug.log (i.e., it does not close the log). If I manually rm -f /var/log/rippled/debug.log, then issuing logrotate successfully reopens the log, so it seems like an issue with closing the log file.

Documentation indicates that the logrotate command "closes and reopens the log file."

I can replicate the issue on two servers, both running rippled 1.2.2 & CentOS 7.

As a minor addition, the compulsive part of me thinks it makes sense for the command to be log_rotate for overall consistency.

[alloyxrp]

I can confirm that the same issue occurs in Ubuntu 16.04

[alloyxrp]

Further investigation (thanks @mellery451 ) shows that the rippled logrotate method is supposed to be used with external log rotation mechanisms. See : https://developers.ripple.com/logrotate.html
In the current form of the code, the method can be done away with completely, and replaced with logrotate.d such as:
/etc/logrotate.d/rippled

/var/log/rippled/*.log {
    missingok
    notifempty
    daily
    rotate 10
    copytruncate
    compress
    create 0644 rippled rippled
}

While this does not help Windows based installations, neither does the rippled logrotate method. It simply opens and closes the log file. No rotation.
I think we should actively consider moving to logrotate.d and include it in the packaging.
@nbougalis

[mellery451]

First, I think we can acknowledge that the name of this method is misleading at best. that said, it turns out that it does exactly the right thing for use with external log rotation mechanisms (logrotate being the standard on most linux distros). I think logrotate issues SIGHUP by default, but for various legacy reasons, rippled already uses SIGHUP and SIGINT to terminate...so that doesn't work. So this logrotate method fits nicely into a postrotate stanza for logrotate config, e.g. something like:

"/var/log/rippled/*.log" {
  daily
  rotate 10
  nocreate
  compress
  compresscmd /usr/bin/nice
  compressoptions -n19 ionice -c3 gzip
  compressext .gz
  postrotate
    /opt/ripple/bin/rippled --conf /etc/opt/ripple/rippled.cfg logrotate
  endscript
}

Regarding the initial experiment, something like this might help clarify how this all works:

mv debug.log debug.log.1 && /opt/ripple/bin/rippled --conf /opt/ripple/etc/rippled.cfg logrotate && ls -latr

The copytruncate option proposed above is another way to configure logrotate, but it runs the risk of losing log lines since it's possible for lines to be written after the copy but before the truncate. Using the move + logrotate insures nothing is lost because the internal command can hold-off log writes until the close/reopen has completed.

FWIW, I've tested this same mechanism on macos (using the homebrew logrotate) and it works as expected). On windows, if the filesystem still disallows renames while open then I suspect the move and close/open will probably not work - more investigation needed there.

In summary, I think this method is possibly poorly named but works as designed for use with logrotate.

[alloyxrp]

Thanks @mellery451 . I think this logrotate snippet should be included in the packaging as /etc/logrotate.d/rippled . Also the developer docs need to reflect this in the rippled logrotate method.

[mellery451]

@mDuo13 what do you think about adding a little extra info to the docs about the specifics of using this method, maybe including sample postrotate command?

[crypticrabbit]

@mellery451, I assume most people probably log at less verbose levels (since debug & trace are verbose to the point of consuming massive amounts of space).

Thus, I think having a default logrotate.d configuration that rotates daily and keeps 10 logfiles may make it needlessly more difficult (i.e., having to review multiple files or only having 10 days of log history) to review logs, as there isn't particularly a need to rotate daily for warn or error.

Adding minsize in the above method could provide a nice balance across log levels.

[MarkusTeufelberger]

Logging should be structured and remote anyways, having more than a few days as backup locally on disk of the actual machine is overkill anyways imho, I'd cut down the logrotate rotate setting down to 5 or so, since by default (without limiting the log settings with the startup RPC call in the config file) logs are quite spammy already.

[nbougalis]

@mellery451: I think we can and should reevaluate the SIGHUP/SIGINT situation, and bring rippled more inline with the convention about these signals; granted, we're unlikely to ever support full config file reloading, but we could behave better.

Not for this issue, but something to consider.

@MarkusTeufelberger: I agree with you about logging; we also need to distinguish between log types; there's "programmer" logging (e.g. _"Need 119 bytes, rounding up to 128"_) were unstructured and local is fine and there's logging for operations (e.g. _"[Thu Jun 13 18:56:29 2019] [connection:info] [client 192.168.0.183:51235] [version rippled-1.2.4]"_) were structured and remote are good.

This is a big project, sorting out existing logging out and implementing the new stuff. Would you be interested in actively contributing to the effort? Even if it's only to review proposals.

[mDuo13]

I'm going to need more than the above example to provide docs I'm happy with for this, but we could totally add a brief tutorial about automating log rotation using the logrotate command.

[mellery451]

93232ec7dfb4d47ba8552ad01d2f18cab63c53d8 adds a logrotate config to packages. Closing this issue, but feel free to open new issues if there are unresolved concerns.