Skip to content

HTTPS clone URL

Subversion checkout URL

You can clone with HTTPS or Subversion.

Download ZIP

Loading…

Reopen log file on SIGHUP #917

Merged
merged 2 commits into from

8 participants

@mndrix

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
Owner

Will this compile on windows/OSX/...?

@mndrix

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

"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

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

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

@mndrix

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

src/util.cpp
((5 lines not shown))
if (!fileout)
{
- char pszFile[MAX_PATH+100];
- GetDataDir(pszFile);
- strlcat(pszFile, "/debug.log", sizeof(pszFile));
+ const char* pszFile = GetDebugLogName().c_str();
@luke-jr
luke-jr added a note

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

@mndrix
mndrix added a note

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
luke-jr added a note

This is the equivalent of (in C):

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

Try this:

std::string file = GetDebugLogName();
fileout = fopen(file.c_str(), "a");
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
@mndrix

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

@luke-jr

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

@laanwj
Owner

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

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
Owner

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

ACK

@rebroad

-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
Owner

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

@rebroad

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

@laanwj
Owner
@rebroad

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
Owner
@rebroad

@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

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

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

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

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

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

@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

@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
Owner

@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
Owner

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

Let's get this merged.

@jgarzik
Owner

Code review comments:

1) Is freopen(3) guaranteed to always return orig_stream? It seems unwise to discard the !NULL return value, if not downright incorrect.

2) 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
Owner

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
1) Is freopen(3) guaranteed to always return orig_stream?

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

I'm certain that boost has a thread locking primitive that may be statically initialized, and available immediately at startup

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
Owner

1) Agreed, freopen(stream) returns stream. ACK there.

2) 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

Rebased and updated to use boost::mutex

@jgarzik
Owner

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.

mndrix added some commits
@mndrix mndrix 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)
fea2571
@mndrix mndrix 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.
9af080c
@mndrix

Good suggestions. Updated.

@jgarzik
Owner

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

@sipa sipa merged commit 63407fd into from
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Commits on May 18, 2012
  1. @mndrix

    Serialize access to debug.log stream

    mndrix authored
    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)
  2. @mndrix

    Reopen debug.log on SIGHUP

    mndrix authored
    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.
This page is out of date. Refresh to see the latest.
Showing with 24 additions and 1 deletion.
  1. +11 −1 src/init.cpp
  2. +12 −0 src/util.cpp
  3. +1 −0  src/util.h
View
12 src/init.cpp
@@ -80,6 +80,10 @@ void HandleSIGTERM(int)
fRequestShutdown = true;
}
+void HandleSIGHUP(int)
+{
+ fReopenDebugLog = true;
+}
@@ -285,7 +289,13 @@ bool AppInit2()
sa.sa_flags = 0;
sigaction(SIGTERM, &sa, NULL);
sigaction(SIGINT, &sa, NULL);
- sigaction(SIGHUP, &sa, NULL);
+
+ // Reopen debug.log on SIGHUP
+ struct sigaction sa_hup;
+ sa_hup.sa_handler = HandleSIGHUP;
+ sigemptyset(&sa_hup.sa_mask);
+ sa_hup.sa_flags = 0;
+ sigaction(SIGHUP, &sa_hup, NULL);
#endif
fTestNet = GetBoolArg("-testnet");
View
12 src/util.cpp
@@ -25,6 +25,7 @@ namespace boost {
#include <boost/filesystem.hpp>
#include <boost/filesystem/fstream.hpp>
#include <boost/foreach.hpp>
+#include <boost/thread.hpp>
#include <openssl/crypto.h>
#include <openssl/rand.h>
#include <stdarg.h>
@@ -69,6 +70,7 @@ bool fTestNet = false;
bool fNoListen = false;
bool fLogTimestamps = false;
CMedianFilter<int64> vTimeOffsets(200,0);
+bool fReopenDebugLog = false;
// Init openssl library multithreading support
static CCriticalSection** ppmutexOpenSSL;
@@ -209,6 +211,16 @@ inline int OutputDebugStringF(const char* pszFormat, ...)
if (fileout)
{
static bool fStartedNewLine = true;
+ static boost::mutex mutexDebugLog;
+ boost::mutex::scoped_lock scoped_lock(mutexDebugLog);
+
+ // reopen the log file, if requested
+ if (fReopenDebugLog) {
+ fReopenDebugLog = false;
+ boost::filesystem::path pathDebug = GetDataDir() / "debug.log";
+ if (freopen(pathDebug.string().c_str(),"a",fileout) != NULL)
+ setbuf(fileout, NULL); // unbuffered
+ }
// Debug print useful for profiling
if (fLogTimestamps && fStartedNewLine)
View
1  src/util.h
@@ -121,6 +121,7 @@ extern std::string strMiscWarning;
extern bool fTestNet;
extern bool fNoListen;
extern bool fLogTimestamps;
+extern bool fReopenDebugLog;
void RandAddSeed();
void RandAddSeedPerfmon();
Something went wrong with that request. Please try again.