Browse Source

Buffer log messages and explicitly open logs

Prevents stomping on debug logs in datadirs that are locked by other
instances and lost parameter interaction messages that can get wiped by
ShrinkDebugFile().

The log is now opened explicitly and all emitted messages are buffered
until this open occurs.  The version message and log cut have also been
moved to the earliest possible sensible location.
0.13
Adam Weiss 10 years ago
parent
commit
27d7605804
  1. 9
      src/init.cpp
  2. 103
      src/util.cpp
  3. 1
      src/util.h

9
src/init.cpp

@ -667,6 +667,9 @@ bool AppInit2(boost::thread_group& threadGroup, CScheduler& scheduler)
fLogTimestamps = GetBoolArg("-logtimestamps", true); fLogTimestamps = GetBoolArg("-logtimestamps", true);
fLogIPs = GetBoolArg("-logips", false); fLogIPs = GetBoolArg("-logips", false);
LogPrintf("\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n");
LogPrintf("Bitcoin version %s (%s)\n", FormatFullVersion(), CLIENT_DATE);
// when specifying an explicit binding address, you want to listen on it // when specifying an explicit binding address, you want to listen on it
// even when -connect or -proxy is specified // even when -connect or -proxy is specified
if (mapArgs.count("-bind")) { if (mapArgs.count("-bind")) {
@ -909,8 +912,10 @@ bool AppInit2(boost::thread_group& threadGroup, CScheduler& scheduler)
#endif #endif
if (GetBoolArg("-shrinkdebugfile", !fDebug)) if (GetBoolArg("-shrinkdebugfile", !fDebug))
ShrinkDebugFile(); ShrinkDebugFile();
LogPrintf("\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n");
LogPrintf("Bitcoin version %s (%s)\n", FormatFullVersion(), CLIENT_DATE); if (fPrintToDebugLog)
OpenDebugLog();
LogPrintf("Using OpenSSL version %s\n", SSLeay_version(SSLEAY_VERSION)); LogPrintf("Using OpenSSL version %s\n", SSLeay_version(SSLEAY_VERSION));
#ifdef ENABLE_WALLET #ifdef ENABLE_WALLET
LogPrintf("Using BerkeleyDB version %s\n", DbEnv::version(0, 0, 0)); LogPrintf("Using BerkeleyDB version %s\n", DbEnv::version(0, 0, 0));

103
src/util.cpp

@ -167,23 +167,51 @@ instance_of_cinit;
*/ */
static boost::once_flag debugPrintInitFlag = BOOST_ONCE_INIT; static boost::once_flag debugPrintInitFlag = BOOST_ONCE_INIT;
/** /**
* We use boost::call_once() to make sure these are initialized * We use boost::call_once() to make sure mutexDebugLog and
* in a thread-safe manner the first time called: * vMsgsBeforeOpenLog are initialized in a thread-safe manner.
*
* NOTE: fileout, mutexDebugLog and sometimes vMsgsBeforeOpenLog
* are leaked on exit. This is ugly, but will be cleaned up by
* the OS/libc. When the shutdown sequence is fully audited and
* tested, explicit destruction of these objects can be implemented.
*/ */
static FILE* fileout = NULL; static FILE* fileout = NULL;
static boost::mutex* mutexDebugLog = NULL; static boost::mutex* mutexDebugLog = NULL;
static list<string> *vMsgsBeforeOpenLog;
static int FileWriteStr(const std::string &str, FILE *fp)
{
return fwrite(str.data(), 1, str.size(), fp);
}
static void DebugPrintInit() static void DebugPrintInit()
{ {
assert(fileout == NULL);
assert(mutexDebugLog == NULL); assert(mutexDebugLog == NULL);
mutexDebugLog = new boost::mutex();
vMsgsBeforeOpenLog = new list<string>;
}
void OpenDebugLog()
{
boost::call_once(&DebugPrintInit, debugPrintInitFlag);
boost::mutex::scoped_lock scoped_lock(*mutexDebugLog);
assert(fileout == NULL);
assert(vMsgsBeforeOpenLog);
boost::filesystem::path pathDebug = GetDataDir() / "debug.log"; boost::filesystem::path pathDebug = GetDataDir() / "debug.log";
fileout = fopen(pathDebug.string().c_str(), "a"); fileout = fopen(pathDebug.string().c_str(), "a");
if (fileout) setbuf(fileout, NULL); // unbuffered if (fileout) setbuf(fileout, NULL); // unbuffered
mutexDebugLog = new boost::mutex(); // dump buffered messages from before we opened the log
while (!vMsgsBeforeOpenLog->empty()) {
FileWriteStr(vMsgsBeforeOpenLog->front(), fileout);
vMsgsBeforeOpenLog->pop_front();
}
delete vMsgsBeforeOpenLog;
vMsgsBeforeOpenLog = NULL;
} }
bool LogAcceptCategory(const char* category) bool LogAcceptCategory(const char* category)
@ -215,44 +243,67 @@ bool LogAcceptCategory(const char* category)
return true; return true;
} }
/**
* fStartedNewLine is a state variable held by the calling context that will
* suppress printing of the timestamp when multiple calls are made that don't
* end in a newline. Initialize it to true, and hold it, in the calling context.
*/
static std::string LogTimestampStr(const std::string &str, bool *fStartedNewLine)
{
string strStamped;
if (!fLogTimestamps)
return str;
if (*fStartedNewLine)
strStamped = DateTimeStrFormat("%Y-%m-%d %H:%M:%S", GetTime()) + ' ' + str;
else
strStamped = str;
if (!str.empty() && str[str.size()-1] == '\n')
*fStartedNewLine = true;
else
*fStartedNewLine = false;
return strStamped;
}
int LogPrintStr(const std::string &str) int LogPrintStr(const std::string &str)
{ {
int ret = 0; // Returns total number of characters written int ret = 0; // Returns total number of characters written
static bool fStartedNewLine = true;
if (fPrintToConsole) if (fPrintToConsole)
{ {
// print to console // print to console
ret = fwrite(str.data(), 1, str.size(), stdout); ret = fwrite(str.data(), 1, str.size(), stdout);
fflush(stdout); fflush(stdout);
} }
else if (fPrintToDebugLog && AreBaseParamsConfigured()) else if (fPrintToDebugLog)
{ {
static bool fStartedNewLine = true;
boost::call_once(&DebugPrintInit, debugPrintInitFlag); boost::call_once(&DebugPrintInit, debugPrintInitFlag);
if (fileout == NULL)
return ret;
boost::mutex::scoped_lock scoped_lock(*mutexDebugLog); boost::mutex::scoped_lock scoped_lock(*mutexDebugLog);
// reopen the log file, if requested string strTimestamped = LogTimestampStr(str, &fStartedNewLine);
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 // buffer if we haven't opened the log yet
if (fLogTimestamps && fStartedNewLine) if (fileout == NULL) {
ret += fprintf(fileout, "%s ", DateTimeStrFormat("%Y-%m-%d %H:%M:%S", GetTime()).c_str()); assert(vMsgsBeforeOpenLog);
if (!str.empty() && str[str.size()-1] == '\n') ret = strTimestamped.length();
fStartedNewLine = true; vMsgsBeforeOpenLog->push_back(strTimestamped);
}
else else
fStartedNewLine = false; {
// reopen the log file, if requested
ret = fwrite(str.data(), 1, str.size(), fileout); if (fReopenDebugLog) {
fReopenDebugLog = false;
boost::filesystem::path pathDebug = GetDataDir() / "debug.log";
if (freopen(pathDebug.string().c_str(),"a",fileout) != NULL)
setbuf(fileout, NULL); // unbuffered
}
ret = FileWriteStr(strTimestamped, fileout);
}
} }
return ret; return ret;
} }

1
src/util.h

@ -125,6 +125,7 @@ void ReadConfigFile(std::map<std::string, std::string>& mapSettingsRet, std::map
boost::filesystem::path GetSpecialFolderPath(int nFolder, bool fCreate = true); boost::filesystem::path GetSpecialFolderPath(int nFolder, bool fCreate = true);
#endif #endif
boost::filesystem::path GetTempPath(); boost::filesystem::path GetTempPath();
void OpenDebugLog();
void ShrinkDebugFile(); void ShrinkDebugFile();
void runCommand(const std::string& strCommand); void runCommand(const std::string& strCommand);

Loading…
Cancel
Save