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 to prevent messages from appearing “before the cut.”
Thanks @jgarzik for setting me on the right track.
Concept ACK; I like making opening the debug log explicit.
This will correctly handle any sequence of Shutdown() being called after AppInit2 errored out somewhere along the way? (just asking - previous changes in this sequence have tended to cause unexpected problems there)
It will now. I wasn’t able to get it to crash in my testing, but I believe that it was possible if the list/buffer were left static.
I believe the issue you’re bringing up is #1832 where the mutex that protects the log was being destroyed before the log print functions were being called resulting in a crash on shutdown. The fix for that was to explicitly initialize the mutex and put it on the heap. This generally results in a leak of the mutex and the output fd even on clean shutdown, but that’s just merely ugly and benign. (and to be clear, the way things are today)
I now do the same with this buffer which will ensure that it is safe, but also leaked at exit along with the mutex and fd. I looked into cleaning up the shutdown stuff and explicitly destroying the mutex, closing the fd and deleting this buffer, but that’s more involved (things are slightly different under QT and bitcoind) and it seems like different, more complex and more difficult to test PR that should probably stand alone.
181 */
182 static FILE* fileout = NULL;
183 static boost::mutex* mutexDebugLog = NULL;
184+static list<string> *vMsgsBeforeOpenLog;
185+
186+int LogWriteStr(const std::string &str)
FileWriteStr, and pass in the file argument explicitly. This makes for a clearer utility function.
237@@ -214,6 +238,24 @@ bool LogAcceptCategory(const char* category)
238 return true;
239 }
240
241+std::string LogTimestampStr(const std::string &str)
bool& fStartedNewLine explicitly, so that it can be defined at the caller site. An utility function with internal state is impossible to use from different contexts (not that it matters at this point, but to avoid surprises in the future).
209- mutexDebugLog = new boost::mutex();
210+ // dump buffered messages from before we opened the log
211+ while (!vMsgsBeforeOpenLog->empty()) {
212+ LogWriteStr(vMsgsBeforeOpenLog->front());
213+ vMsgsBeforeOpenLog->pop_front();
214+ }
vMsgsBeforeOpenLog here and set it to NULL.
290- ret += fprintf(fileout, "%s ", DateTimeStrFormat("%Y-%m-%d %H:%M:%S", GetTime()).c_str());
291- if (!str.empty() && str[str.size()-1] == '\n')
292- fStartedNewLine = true;
293+ // buffer if we haven't opened the log yet
294+ if (fileout == NULL) {
295+ ret = strTimestamped.length();
306+ boost::filesystem::path pathDebug = GetDataDir() / "debug.log";
307+ if (freopen(pathDebug.string().c_str(),"a",fileout) != NULL)
308+ setbuf(fileout, NULL); // unbuffered
309+ }
310+
311+ ret += LogWriteStr(strTimestamped);
ret += here, and ret = in the other fork of the if()?
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.
Labels
Refactoring