libs)

Jul 14, 2021

https://github.com/bitcoin/bitcoin/pull/22350

Host: larryruane - PR author: larryruane

The PR branch HEAD was ea728a306 at the time of this review club meeting.

This week, we’ll look at PR 22350 that proposes to rotate the debug.log file on disk. Four weeks ago, we reviewed PR 21603; this PR is an alternative.

This time we’re going to try something different – LarryRuane will host a video chat at https://meet.jit.si/bitcoin-core-pr-reviews-22350 (recording, notes) and all are invited to join! We’ll also use IRC as usual (we’ll see how this goes).

The purpose of the video meeting is that Larry will share his display and show how one might use the gdb debugger as an aid to reviewing this or any PR. The session will be recorded, and the link to the recording sent out with the IRC log after the meeting.

Bitcoin Core developer Fabian Jahr has provided an excellent document and video on using the system debugger and much more. Larry will more narrowly focus on using gdb effectively.

Notes

Please review to the Notes for the PR 21603 review for background information about logging.
Many operating systems solve the logging growth problem by automatically rotating their system logs; run ls /var/log on any Linux system and you’ll likely see several different kinds of log files with numbers as part of their filenames; these are “rotated” log files – older versions of the main log file. Some of these are also compressed.

$ ls /var/log
alternatives.log  boot.log       dpkg.log.2.gz      fail2ban.log.3.gz  lastlog           log2ram.log                 mynode.log              rtl.log.2                       unlock_lnd.log
apt               bootstrap.log  dpkg.log.3.gz      fail2ban.log.4.gz  lit.log           loopd.log                   mynode.log.1            syslog                          unlock_lnd.log.1
auth.log          btmp           dpkg.log.4.gz      faillog            lit.log.1         loopd.log.1                 mynode.log.2            syslog.1                        unlock_lnd.log.2
auth.log.1        btmp.1         dpkg.log.5.gz      flask              lit.log.2         loopd.log.2                 mynode_quicksync.log    sysstat                         upgrade.log
auth.log.2        daemon.log     dpkg.log.6.gz      flask.1            lnd_backup.log    loop.log                    mynode_quicksync.log.1  tor                             user.log
bitcoind.log      daemon.log.1   electrs.log        flask.2            lnd_backup.log.1  messages                    mynode_quicksync.log.2  ufw.log                         user.log.1
bitcoind.log.1    debug          electrs.log.1      fontconfig.log     lnd_backup.log.2  messages.1                  nginx                   ufw.log.1                       user.log.2
bitcoind.log.2    debug.1        electrs.log.2      gunicorn           lndconnect.log    messages.2                  private                 ufw.log.1.gz-2021060600.backup  wtmp
bitcoin.log       debug.2        fail2ban.log       kern.log           lnd.log           mynode_docker_images.log    redis                   ufw.log.2.gz                    www.log
bitcoin.log.1     dpkg.log       fail2ban.log.1     kern.log.1         lnd.log.1         mynode_docker_images.log.1  rtl.log                 ufw.log.3.gz                    www.log.1
bitcoin.log.2     dpkg.log.1     fail2ban.log.2.gz  kern.log.2         lnd.log.2         mynode_docker_images.log.2  rtl.log.1               ufw.log.4.gz                    www.log.2

Linux and other Unix-like systems include a tool specialized to this exact task, logrotate. It’s usually configured to run periodically (daily, for example) using the built-in cron facility.
The logrotate command is difficult to configure (run man logrotate), knowledge of cron is also required, and is not available on Windows or on some stripped-down Linux distributions.
For that reason, some programs do their own internal log rotation. The concept is, when a log file reaches a certain size, the system that “owns” the log file renames it to an alternate name (usually by including a sequence number), and resets the main log file to empty. Usually this occurs as a side-effect of writing a log message.
Different things can be done with the rotated log files. For example:
- Retain only a configurable number of the most recent log files, deleting older files.
- Compress and save the rotated log files for a configurable time period.
- Upload the log files to a remote system that can archive them (store them cheaply).
Many commercial data storage systems do internal log file rotation (examples here and here).
While Bitcoin Core’s debug.log file grows without limit for as long as bitcoind runs, it does do one kind of trimming: When bitcoind starts up, it checks the length of debug.log; if it’s greater than 11 MB, it shrinks it down to the most recent 10 MB of logging data.

Questions

Did you review the PR? Concept ACK, approach ACK, tested ACK, or NACK? What was your review approach?
Why does bitcoind include the concept of a log file? It uses disk space; what’s the advantage? Have you needed to look at debug.log; has it been useful?
What’s the connection with denial-of-service attacks?
If we receive an invalid transaction, why don’t we log that this happened? Should we?
PR 21603 uses a different approach, log rate limiting. (Quick summary: Parts of the code that are generating too much logging too quickly are throttled; not all their log messages are saved, although this limiting itself is logged so readers of the log are aware that it’s happened.) What are the advantages and disadvantages of these two approaches? Which do you think would result in more useful log output?
Other log rotation systems append a sequence number to rotated logs (for example, on Linux systems, in /var/log, you see syslog.1, syslog.2, … This PR names the rotated log files by date, such as debug-2021-06-27T21:19:42Z.log. What are the trade-offs? Which naming style do you prefer?
Should this PR also compress rotated log files?
Is this PR even necessary, given that the logrotate facility exists? What are the trade-offs?
On Linux systems, logrotate is located in /usr/sbin. What kinds of programs are stored there, as opposed to the more standard /usr/bin?

Video

Larry has recorded a video tutorial on using GDB to accompany this Review Club meeting, with accompanying notes.