Buffer log messages and explicitly open logs #6149

Merged
merged 1 commit into from Jul 22, 2015

Conversation

Projects
None yet
3 participants
@ajweiss
Contributor

ajweiss commented May 16, 2015

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.

@laanwj laanwj added the Refactoring label May 16, 2015

@laanwj

This comment has been minimized.

Show comment
Hide comment
@laanwj

laanwj May 16, 2015

Member

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)

Member

laanwj commented May 16, 2015

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)

@ajweiss

This comment has been minimized.

Show comment
Hide comment
@ajweiss

ajweiss May 18, 2015

Contributor

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.

Contributor

ajweiss commented May 18, 2015

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.

src/util.cpp
*/
static FILE* fileout = NULL;
static boost::mutex* mutexDebugLog = NULL;
+static list<string> *vMsgsBeforeOpenLog;
+
+int LogWriteStr(const std::string &str)

This comment has been minimized.

@laanwj

laanwj Jun 1, 2015

Member

This function can be static

@laanwj

laanwj Jun 1, 2015

Member

This function can be static

This comment has been minimized.

@laanwj

laanwj Jun 1, 2015

Member

Also I'd suggest to rename it to FileWriteStr, and pass in the file argument explicitly. This makes for a clearer utility function.

@laanwj

laanwj Jun 1, 2015

Member

Also I'd suggest to rename it to FileWriteStr, and pass in the file argument explicitly. This makes for a clearer utility function.

src/util.cpp
@@ -214,6 +238,24 @@ bool LogAcceptCategory(const char* category)
return true;
}
+std::string LogTimestampStr(const std::string &str)

This comment has been minimized.

@laanwj

laanwj Jun 1, 2015

Member

Function can be static

@laanwj

laanwj Jun 1, 2015

Member

Function can be static

This comment has been minimized.

@laanwj

laanwj Jun 1, 2015

Member

I'd suggest passing in 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).

@laanwj

laanwj Jun 1, 2015

Member

I'd suggest passing in 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).

src/util.cpp
+ while (!vMsgsBeforeOpenLog->empty()) {
+ LogWriteStr(vMsgsBeforeOpenLog->front());
+ vMsgsBeforeOpenLog->pop_front();
+ }

This comment has been minimized.

@laanwj

laanwj Jun 1, 2015

Member

Could delete vMsgsBeforeOpenLog here and set it to NULL.

@laanwj

laanwj Jun 1, 2015

Member

Could delete vMsgsBeforeOpenLog here and set it to NULL.

src/util.cpp
- fStartedNewLine = true;
+ // buffer if we haven't opened the log yet
+ if (fileout == NULL) {
+ ret = strTimestamped.length();

This comment has been minimized.

@laanwj

laanwj Jun 1, 2015

Member

Just to be sure: add assertion that vMsgsBeforeOpenLog is not null

@laanwj

laanwj Jun 1, 2015

Member

Just to be sure: add assertion that vMsgsBeforeOpenLog is not null

src/util.cpp
+ setbuf(fileout, NULL); // unbuffered
+ }
+
+ ret += LogWriteStr(strTimestamped);

This comment has been minimized.

@laanwj

laanwj Jun 1, 2015

Member

Any reason to use ret += here, and ret = in the other fork of the if()?

@laanwj

laanwj Jun 1, 2015

Member

Any reason to use ret += here, and ret = in the other fork of the if()?

@laanwj

This comment has been minimized.

Show comment
Hide comment
@laanwj

laanwj Jul 2, 2015

Member

Needs nits addressed, should otherwise be ready for merging.

Member

laanwj commented Jul 2, 2015

Needs nits addressed, should otherwise be ready for merging.

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.
@ajweiss

This comment has been minimized.

Show comment
Hide comment
@ajweiss

ajweiss Jul 7, 2015

Contributor

Nits addressed and rebased. Waiting for Travis... (which appears to be attempting to build the whole depends tree?)

Contributor

ajweiss commented Jul 7, 2015

Nits addressed and rebased. Waiting for Travis... (which appears to be attempting to build the whole depends tree?)

@jgarzik

This comment has been minimized.

Show comment
Hide comment
@jgarzik

jgarzik Jul 7, 2015

Contributor

lightly tested ACK

Contributor

jgarzik commented Jul 7, 2015

lightly tested ACK

@laanwj

This comment has been minimized.

Show comment
Hide comment
@laanwj

laanwj Jul 22, 2015

Member

Tested ACK

Member

laanwj commented Jul 22, 2015

Tested ACK

@laanwj laanwj merged commit 27d7605 into bitcoin:master Jul 22, 2015

1 check passed

continuous-integration/travis-ci/pr The Travis CI build passed
Details

laanwj added a commit that referenced this pull request Jul 22, 2015

Merge pull request #6149
27d7605 Buffer log messages and explicitly open logs (Adam Weiss)

@str4d str4d referenced this pull request in zcash/zcash Feb 15, 2017

Merged

Bitcoin 0.12 misc PRs 1 #2099

@dagurval dagurval referenced this pull request in bitcoinxt/bitcoinxt Apr 23, 2017

Merged

Util ports #197

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment