Reopen log file on SIGHUP

mndrix commented at 4:38 pm on March 5, 2012: contributor

This pull request is intended to facilitate bitcoind log rotation. When the daemon receives a HUP signal, it reopens the debug.log file so the previous one can be rotated. I’ve tried to describe the technical motivation in each of the three commit messages. It uses flockfile and funlockfile to avoid thread contention issues. As best I can tell, those functions are available on most platforms, but I have only compiled on OS X.

I have a test script which sends SIGHUP to the bitcoind process every 100 ms. I’ve been running with that test script and this patch for the last few days and haven’t had any problems. In my tests, it behaves well during startup and shutdown too. Each rotated log contains the content I expect.

Suggestions for improvement welcome.

sipa commented at 10:45 pm on March 5, 2012: member

Will this compile on windows/OSX/…?

mndrix commented at 11:18 pm on March 5, 2012: contributor

It does compile on OS X. I don’t have a Windows build machine, but Microsoft documentation suggests that they support the necessary APIs.

luke-jr commented at 5:08 am on March 14, 2012: member

“Microsoft Windows Services for UNIX” != Windows. flockfile is not available on Windows (or at least not for MingW), and compiling it in next-test fails…

mndrix commented at 2:54 pm on March 14, 2012: contributor

I’ll update the pull request to only activate flockfile and funlockfile when #ifndef WIN32. We already do that for signal handlers.

One could also try using CreateMutex and WaitForSingleObject to support similar locking semantics on Windows. I don’t have a Windows development machine, so I’d be coding blind trying to implement that approach.

luke-jr commented at 3:03 pm on March 14, 2012: member

“Nobody” has a Windows development machine. Windows builds are produced with gitian on Ubuntu.

mndrix commented at 10:30 pm on March 14, 2012: contributor

I’ve updated the branch so that it’s a noop on Windows

in src/util.cpp: in 0fc2db0dd2 outdated

184         if (!fileout)
185         {
186-            char pszFile[MAX_PATH+100];
187-            GetDataDir(pszFile);
188-            strlcat(pszFile, "/debug.log", sizeof(pszFile));
189+            const char* pszFile = GetDebugLogName().c_str();

luke-jr commented at 4:57 pm on April 10, 2012:

Won’t the std::string temporary from GetDebugLogName() free pszFile before it is used?

mndrix commented at 5:28 pm on April 10, 2012:

I don’t know. I’ve not encountered any problems running with this code. My C++ chops are weak, so I’ll gladly do this differently if there’s a better way.

luke-jr commented at 5:44 pm on April 10, 2012:

This is the equivalent of (in C):

0char *s = malloc(8);
1memcpy(s, "testing", 8);
2free(s);
3fopen(s, "a");

Try this:

0std::string file = GetDebugLogName();
1fileout = fopen(file.c_str(), "a");

mndrix commented at 4:38 pm on April 13, 2012: contributor

Thanks to ee12c3d60c4bb7b25e06709e92344d2d8b2c581e the problem @luke-jr mentioned is no longer an issue. I’ve updated the pull request accordingly.

luke-jr commented at 7:48 pm on April 14, 2012: member

ACK. Planning to (user-optionally) merge this in Gentoo for logrotate support.

laanwj commented at 7:58 am on April 16, 2012: member

Looks like a useful feature.

How does this interact with the log rotation / debug.log size-limiting inside bitcoin itself? I remember seeing some code for that.

mndrix commented at 2:36 pm on April 16, 2012: contributor

I don’t know of any log rotation code inside bitcoin, but this code works well with the size limiting code. ShrinkDebugFile() runs only during startup before debug.log is opened for writing.

laanwj commented at 4:03 pm on April 16, 2012: member

Ok, so that only runs at startup. That’s good.

ACK

rebroad commented at 10:55 pm on April 17, 2012: contributor

-1 from me. I think bitcoin should re-examine the bitcoin.conf file upon receiving a HUP. This, AFAIK is the more standard thing to happen on Unix, isn’t it?

laanwj commented at 5:53 am on April 18, 2012: member

The one does not exclude the other. And keep your -1/+1 out of here please.

rebroad commented at 9:19 am on April 18, 2012: contributor

@laanwj You mean rotate the log file and re-parse bitcoin.conf? -0.99999 to that one ;)

laanwj commented at 9:33 am on April 18, 2012: member

Yes. That’s what most daemons do AFAIK and is sane. Both reopening the log file and re-reading the config file are no-ops if nothing changed to the log file and configuration file respectively.

rebroad commented at 10:10 am on April 18, 2012: contributor

I think it makes more sense to have a config option to specify how many logs files to keep and how often to rotate them. Having the log file rotated every time you want to re-read the config would be not very useful IMHO, as there may be 10000 lines added since the last config change or only 10 lines.

laanwj commented at 10:26 am on April 18, 2012: member

I see no reason at all to include log rotation into bitcoin itself.

There are excellent log rotation tools in common use. The only support they require of the application is reopening the log on a signal (like this pull request does). These have settings to rotate by size, by time, to autocompress old files, and so on.

rebroad commented at 11:39 am on April 18, 2012: contributor

@laanwj I’m not aware of many people using Windows XP (for example) that use log rotation tools, and even if they did, are the tools able to rotate the logs at exactly midnight so that entries from either side of midnight don’t end up in the wrong log file?

Flowdalic commented at 2:33 pm on April 18, 2012: contributor

I would recommend using SIGHUP for config file reloading and SIGUSR1 for logrotation. This is how most daemons do it and how it should be used with logrotate. That’s whats needed for the Gentoo ebuild logrotate use flag and I am sure other distributions would benefit from it too. Rotation of log files should not be done by bitcoind. I am sure there are solutions for win32 users also.

mndrix commented at 3:08 pm on April 18, 2012: contributor

All three examples in the logrotate man page use SIGHUP. The default signal for newsyslog (used on OS X and other BSDs) is SIGHUP. As best I can tell, that’s the closest thing to a standard that exists.

Flowdalic commented at 3:25 pm on April 18, 2012: contributor

On the other hand, many prominent FOSS uses SIGUSR1:

apache
mongodb
dovecot

And my expectation about signals and daemons is that SIGHUP reloads the config file and SIGUSR1 re-opens the log file. Since both actions are not really related to each other, this seems to be a saner approach. And the stackoverflow answer shows that the community thinks so too.

luke-jr commented at 3:28 pm on April 18, 2012: member

All those FOSS you just listed also use USR1 for reloading configs…

But can we just pick one, any one, or maybe even both, and not spend pages discussing the pros/cons of each?

davout commented at 6:25 pm on April 18, 2012: none

IMHO configuration hot-reload isn’t very useful… just my two satoshis… On the other hand log file reopening would be really nice to have

rebroad commented at 9:17 pm on April 18, 2012: contributor

@davout I agree that at present config reload isn’t very useful. I’m tempted to suggest that SIGHUP be reserved for that possibly functionality in future though, and going with SIGUSR1 for the logfile rotation, if that’s the agreed standard. e.g. how does “tor” do things?

I still think it’s not unreasonable for bitcoin to offer to do it’s own log rotation though - people can still choose to use a 3rd party program if they prefer. one or two config options would probably suffice, and it’d be easy to code.

davout commented at 9:27 pm on April 18, 2012: none

@rebroad it is unreasonable to reinvent the wheel. if you don’t care about log rotation you’ll be fine with the log size limit. if you do care you’ll use logrotate.

laanwj commented at 5:55 am on April 19, 2012: member

@rebroad: We want to reduce the complexity of the core, not increase it. Anything that can (sanely) be handled by external utilities, should be. If your platform does not have these utilities, you can port them or switch platform.

Note that log rotation is only useful for servers and services, in which you’d like to keep the old data for auditing purposes. Windows XP users tend to be normal end-users which don’t care about log files at all.

Reloading configuration is an orthogonal option, open a new issue and discuss about it there.

Let’s keep this thread for testing and ACKing this code.

jgarzik commented at 11:22 pm on May 8, 2012: contributor

Reloading config file is very common daemon behavior
Reloading config file is very complex, and far beyond the scope of this pull request
Log rotation is beyond the scope of this pull request.
ACK this pull request, in concept. See code comments for minor nits.

Let’s get this merged.

jgarzik commented at 11:27 pm on May 8, 2012: contributor

Code review comments:

Is freopen(3) guaranteed to always return orig_stream? It seems unwise to discard the !NULL return value, if not downright incorrect.
The “locking” is definitely disappointing… using file locks, which often depend on filesystem-specific behavior, due to lack of CRITICAL_SECTION() is decidedly suboptimal. I’m certain that boost has a thread locking primitive that may be statically initialized, and available immediately at startup.

laanwj commented at 5:29 am on May 9, 2012: member

I assumed that the point of using file locks is you can block the logger from your log rotation tool, so you don’t lose log records during the transition?

mndrix commented at 2:46 pm on May 9, 2012: contributor

My understanding of the documentation on Linux and OS X, leads me to say yes.

I’ve not found such a primitive in the Boost libraries, but may not recognize it if I saw it. I’ll gladly change the locking technique if someone can point me at a better primitive.

jgarzik commented at 2:50 pm on May 15, 2012: contributor

Agreed, freopen(stream) returns stream. ACK there.
As one would expect, boost::mutex is a proper C++ class, and is available properly initialized (unlocked) as soon as the class is instantiated. Here is a non-threaded working example: https://gist.github.com/2702335

mndrix commented at 5:50 pm on May 18, 2012: contributor

Rebased and updated to use boost::mutex

jgarzik commented at 7:38 pm on May 18, 2012: contributor

Changes look good, except for one: you made ‘fileout’ a global variable, when the existing, more narrowly-scoped ‘static’ declaration is preferred.

Might consider making that static mutex more narrowly scoped like ‘fileout’, too.

Serialize access to debug.log stream

Acquire an exclusive, advisory lock before sending output to debug.log
and release it when we're done. This should avoid output from multiple
threads being interspersed in the log file.

We can't use CRITICAL_SECTION machinery for this because the debug log
is written during startup and shutdown when that machinery is not
available.

(Thanks to Gavin for pointing out the CRITICAL_SECTION problems based
on his earlier work in this area)

fea25712ca

Reopen debug.log on SIGHUP

The best log rotation method formerly available was to configure
logrotate with the copytruncate option.  As described in the logrotate
documentation, "there is a very small time slice between copying the
file and truncating it, so some logging data might be lost".

By sending SIGHUP to the server process, one can now reopen the debug
log file without losing any data.

9af080c351

mndrix commented at 10:40 pm on May 18, 2012: contributor

Good suggestions. Updated.

jgarzik commented at 10:44 pm on May 18, 2012: contributor

ACK, looks perfect to me. Thanks for your patience.

sipa referenced this in commit 63407fd6e2 on May 21, 2012

sipa merged this on May 21, 2012

sipa closed this on May 21, 2012

coblee referenced this in commit 394624e7a0 on Jul 17, 2012

suprnurd referenced this in commit 8f9544c46e on Dec 5, 2017

lateminer referenced this in commit b38ef04838 on Oct 30, 2019

DrahtBot locked this on Sep 8, 2021

Reopen log file on SIGHUP #917