take steps towards standardizing and improving log output

[shea256]

I made a few updates to improve the log outputs and work towards standardizing the outputs.

I tried to uncover the closest thing to a convention that I could. And here are the principles that I gleaned:

• start the line with the log label/type followed by a colon
• have the log label start with a capital letter and be expressed in the present progressive (-ing) or past tense (-ed), depending on whether the event/process is ongoing or an event has been completed
• after the colon, present a list of properties/attributes/details of the output, where each property is expressed with its name followed by the equals sign and then its value
• separate each property by two spaces
• express the property names using camelCase

In addition to these changes, I:

• made sure that "blk" was included in quotes to make it clear to the user that "blk" is a proper name given to a certain type of file and not an actual word.
• included quotes around the names of threads starting up so that it's clear that the threads are referred to by their proper names

A few things that still bother me about the outputs:

• there are a few cases where output lines include single properties that don't follow the output convention, for example: mapBlockIndex.size() = 374551
• nTimeOffset logs are presented in a strange way, where it's unclear that the first value is in seconds (it explicitly says the value after that is in minutes, but that value in my experience is usually zero)
• there are a few cases where the output lines start with a function name rather than describing what is happening, as is the case with most logs (for example connect() to...
• logs starting with UpdateTip could be more descriptive - more specifically, when a new block has been discovered, they should communicate that a new block has been discovered
• "init message" logs seem out of place from other logs

Also, while I stuck with the conventions that I could best glean from the outputs I observed, I would suggest making a few changes to the conventions. Namely, the following:

• start the line with the name of the thread
• enforce that every line after the name of the thread starts with an action in the present progressive or past tense (as most, maybe 80%, of the logs already seem to do)
• either use commas to separate log properties or prohibit property names that include spaces, strictly enforcing a certain case (either camelCase or snake_case)
• combine the init log properties like mapBlockIndex.size() and nBestHeight into a single line and enforce this for other outputs that have multiple properties OR if this is not desired, then have additional newlines separating the outputs to make it clear that those properties are grouped together

[dcousens]

utACK

[jgarzik]

Comments:

• I would dump the util.h changes as "meh"
• Do we care about breaking anyone parsing logs? I say "no"

ut ACK the rest

[paveljanik]

Why two spaces? Are you Satoshi?

[wallclockbuilder]

ACK

[laanwj]

I'd say "meh".

There's an infinite number of these pulls that could be created , that make small changes to the log format here and there, perturbing a line here and there.

But remember that the log is just a debug log. Its format is not meant to be standardized or machine parseable. To be concise: it is not a well-defined external interface. You can't really speak of convention.

Maybe there should be one - but then I think this could work if you first write and add a document describing guidelines/rules for the log format, then apply that consistently everywhere and also commit to reviewing new pull requests that they stick to the format.

[TheBlueMatt]

I'm generally not a fan of changing debug log format just to change it. It's not designed to be machine parsable, and changing it breaks any existing parsers or people trying to grep old logs across format changes (my debug.log is a few months old and a few hundred gb, which offers useful ability to grep for interesting things).

On September 17, 2015 12:38:35 PM EDT, "Wladimir J. van der Laan" notifications@github.com wrote:

I'd say "meh".

There's an infinite number of these pulls that could be created , that
make small changes to the log format here and there, perturbing a line
here and there.

But remember that the log is just a debug log. Its format is not meant
to be standardized or machine parseable. To be concise: it is not a
well-defined external interface. You can't really speak of convention.

Maybe there should be one - but then I think this could work if you
first write and add a document describing guidelines/rules for the log
format, then apply that consistently everywhere and also commit to
reviewing new pull requests that they stick to the format.

---

Reply to this email directly or view it on GitHub:
#6674 (comment)

[shea256]

@laanwj My goal with this PR was to glean a standard as best as I could. I noticed that there were certain things that were common across the various log messages, and so I went with whatever patterns were found there.

I do think that there should be a convention and I would be happy to help develop one. As you can see, I started taking notes on conventions above.

I understand that it's just a debug log but I actually think it is just another thing that can make developers' lives happy when they have to parse through the logs. When logs are more human readable this does actually make it simpler to parse through things. When one has to figure out what this or that means, that results in that much more time for a developer to address issues and that much more value lost in terms of application value or contributions back to bitcoin core.

Further, I think this also is an issue of professionalism for a piece of software that should be up there with the most professional ones, given it's societal importance.

"Paint the back of the fence... because you'll know."

@paveljanik the reason I went with two spaces is that seemed to be the favored method and if you only use one space, there's not a clear separation between properties, unless of course you use some other delineator like commas, which I would also support (that's probably even cleaner).

@TheBlueMatt The point here was not to change the debug log format just to change it. I was motivated to submit this PR after spending time going through the logs and realizing how they should have been much easier to parse. You all are much more familiar with what all of the log messages are for, but I'd put yourselves in the position of a developer working with bitcoind early on.

[laanwj]

"Paint the back of the fence... because you'll know."

I'm not deeply against it, just a bit afraid that if this is done uncoordinated it will open the floodgates to zillions of pull requests that will just change a logging line here and there. This makes history hard to read, and may interfere with more important changes.

We've seen this before with proposals to e.g. sort the include files at the top of implementation files. Its nice if it is sticked to consistently, but if not it gives a lot of extra traffic for questionable gain.

As it is there's still plenty of painting at the front of the fence that needs to be done.

Edit: so to be concrete: first add a document to doc/XXX, make people agree on the new convention for log messages (if there is interest in it), and only then apply it.

[shea256]

Edit: so to be concrete: first add a document to doc/XXX, make people agree on the new convention for log messages (if there is interest in it), and only then apply it.

Sounds like a plan. I can propose one and submit it.

[laanwj]

Ok looking forward to that, closing this pull in the meantime