lightning icon indicating copy to clipboard operation
lightning copied to clipboard

Optional simultaneous debug logging to second file?

Open wtogami opened this issue 1 year ago • 6 comments

Background #5349 was helpful in enabling debug logging to zoom in on one particular peer node id. It would sometimes be useful when you know in advance how to reproduce an issue. The trouble however is with many rare issues you can't predict ahead of time like #5371 or you can't restart the daemon to change the log-level because doing so workarounds the problem like #5366. Thus if we want better info to always be available we need debug logging enabled. But the full debug firehose is too much to drink. It contains too many useless events that detract from your ability to see ordinary information in the regular info log.

Proposal: Add an optional simultaneous second log file

# Existing log options behave exactly as before 
log-file=/var/log/lightningd/info.log
log-level=info
log-level=debug:plugin-peerswap-plugin
log-level=debug:02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f
# Second log file
log2-file=/var/log/lightningd/debug.log
log2-level=debug

With the option for two log files you could have the best of both worlds. The normal log would remain useful while users can opt into a second debug log containing whatever firehose they want. That way when an unpredictable bug happens the best possible information is available for reporting.

Notes

  • log2 would be disabled by default. log2-file can only be a file, not stdout like the default behavior of the main log.
  • Documentation would show an example using logrotate to rotate the log2-file every day with 7 days expiry. This should be long enough firehose retention to recover whatever info is needed from a recent event. SIGHUP should behave the same on both log files.

Thoughts?

wtogami avatar Jul 09 '22 07:07 wtogami

Already implemented for 0.12: https://github.com/ElementsProject/lightning/pull/5281/commits/6ed5f3153b19889391f7df4e8edef0d3ac2d3500

rustyrussell avatar Jul 09 '22 09:07 rustyrussell

Would it be feasible to have separate filtering for each log file like the above example? It appears that isn't currently implemented?

wtogami avatar Jul 09 '22 09:07 wtogami

Hmm, maybe we allow filename at the beginning of 'log-level', like:

log-file=/var/log/lightningd/info.log
log-level=/var/log/lightningd/info.log:info

Awkward, but allows : in log filenames.

rustyrussell avatar Jul 14 '22 08:07 rustyrussell

That would be great, especially if it would allow for the same level of granularity as before.

This way you can have your regular info level log and a channel specific debug log to another destination.

zerofeerouting avatar Jul 26 '22 08:07 zerofeerouting

@rustyrussell - just a quick question - would it look like this?

log-file=/var/log/lightningd/info.log
log-file=/var/log/lightningd/debug-chan55.log
log-level=/var/log/lightningd/info.log:info
log-level=/var/log/lightningd/debug-chan55.log:debug:chan#55

zerofeerouting avatar Jul 26 '22 17:07 zerofeerouting

It would work fine either way but it would be cleaner and less error prone if you specify filenames only once per logX-file entries? You could put colons in those filenames if you want.

wtogami avatar Jul 26 '22 18:07 wtogami