Improve debug.log output. #1311

rebroad commented at 11:08 PM on May 14, 2012: contributor

This change improves debug.log output in the following ways:-

It reduces some duplicate output, and no longer needed output (which was originally added for testing).

It reduces the verbosity of output during initial block download, so rather than showing every block requested, it summarises. Once caught up, the previously level of verbosity is restored.

Information about the nodes connected are shown, and additional information about errors (particularly rejected transactions) are shown, with the offending peer alongside.

Recent changes which add many lines, such as address handling have been kept in as this code is still relatively new - I was tempted to comment out various lines such as the "tried...", etc.

Timestamps is now enabled by default. -nologtimestamps or logtimestamps=0 will disable this.

Also, renamed AlreadyAskedFor to AlreadyWaitingFor (makes more sense, as can cease waiting, but cannot stop having done a past thing.)

gmaxwell commented at 11:18 PM on May 14, 2012: contributor

This makes non-trivial unrelated changes, for example it adds DoS() to node connecting with the old protocol version.

gmaxwell commented at 11:22 PM on May 14, 2012: contributor

Also, NAK on the general introduction of peer address to many messages. I'd be okay with logging the peer address of attack behavior or truly unusual exceptions, but logging by default the address of every peer we pull transactions from is not good and would create considerable incentives to compromise the security of nodes to use their logs for tracing transactions.

jgarzik commented at 11:39 PM on May 14, 2012: contributor

logtimestamps was disabled by default for similar reasons that we don't always log peer address... major privacy implications.

rebroad commented at 11:59 PM on May 14, 2012: contributor

@gmaxwell Doesn't it make more sense to use the misbehaving function on a peer that you will always disconnect whenever it connects? Why not use it?

Re peer addresses: these are changes anyone could do anyway, it is useful debug info, especially when trying to work out why blocks aren't downloading as fast as they could be, or for troubleshooting code to determine network lag in general or per peer. The debug.log is chopped regularly, so there is usually no more than a day or two of logs. Would it help perhaps, if instead of showing IP addresses, it just used a unique number instead? The IP address itself isn't important, but correlating which of several peers is.

Re timestamps, @jgarzik - how is this a privacy implication? With timestamps off, the flushing of the wallet.dat is always timestamped, so a timestamp per line surely makes little difference, does it?

gmaxwell commented at 12:14 AM on May 15, 2012: contributor

The problem isn't that people can do it— it's the expectation that having this creates that going and collecting drives from bitcoin nodes will net you valuable information. Excessive logging endangers our users in several ways— beyond the lost privacy there is the risk of node operators being subject to frivolous fishing expedition investigations just to gather their logs, being hacked to use nodes to trace back nodes, etc.

I don't believe I've ever wanted addresses in the logs of someone elses node I was troubleshooting, except on rpc authentication failures. (I have wanted addresses on my own nodes too, but I can— as you point out— enable that locally).

The default logging behavior shouldn't reflect the logging we as developers user to build the software— it should reflect the logging we need to help users with mysterious behavior out in the field... and thats all. If not for that need we wouldn't have logging at all.
Regarding timestamps— infrequent markers are not the same thing as timestamps on every message.

gmaxwell commented at 12:23 AM on May 15, 2012: contributor

On the misbehaving change— I wasn't complaining that it was a bad change I was complaining that you're mixing changes that require different kinds of review in your pull.

The debug log entries are mostly cosmetic, assuming they aren't outright buggy and ignoring privacy issues the amount of harm changing them is at worst fairly minimal. Whereas a DoS change even if it works perfectly, could knock the whole network out— it requires a different kind of consideration.

As far as it goes, I think it actually is a bad change: It means that when the old node gets upgraded he may be blacklisted by the whole network and not be able to get on for another 24 hours. Because it costs basically no more to hang up due to the blacklist vs hang up at the addr message I don't see that it saves us anything.

rebroad commented at 12:47 AM on May 15, 2012: contributor

Understood. Ok, so DoS to be removed. Timestamps off by default. How about changing it to an option to enable peer logging, that's off by default? Would that be ok then?

fanquake commented at 11:37 AM on May 15, 2012: member

Looks like this pull contains code from other pull requests you've made. Shouldn't each pull request only have the code related to the specific change?

I'm fairly sure this pull also includes the code from here -> #1306 and here -> #1305

rebroad commented at 2:10 PM on May 15, 2012: contributor

@fanquake I just did a git log -p to check, but there's no mention of proxytoo in the entire log history, so I'm not quite sure what you're looking at. oh.. but on github it does show... I'll try pushing again. Ok, I've removed the ProxyToo mention now, thanks for spotting that. An inadvertent merge, not that this'll be enough to get it ACKed. I'll add a flag for the peer logging, as I agree with @gmaxwell that it reduces anonymousness unnecessarily in most situations.

rebroad commented at 2:48 PM on May 15, 2012: contributor

Ok, this now displays peers only if -logpeers is true, and that option isn't advertised unless the code is examined. Peers are shown for blocks, and for Dos(100) transactions only unless the option is selected. Timestamps are disabled by default. DoS for obsolete version also removed. Also, HandleSIGTERM now shows the signal number received.

Thanks for the feedback @gmaxwell, hopefully this is a more agreeable edit now.

rebroad commented at 5:03 PM on May 17, 2012: contributor

This pull now contains no functional changes, only display changes.

jgarzik commented at 5:20 PM on May 17, 2012: contributor

meh, this thing is still freakin' huge, touching all sorts of code.

will post a few comments inline...

in src/addrman.h:None in 22251182f9 outdated

 433 | @@ -434,7 +434,7 @@ class CAddrMan
 434 |                  nAdd += Add_(*it, source, nTimePenalty) ? 1 : 0;
 435 |              Check();
 436 |          }
 437 | -        if (nAdd)
 438 | +        if (nAdd && CaughtUp())

jgarzik commented at 5:22 PM on May 17, 2012:

NAK, I like these unconditional

rebroad commented at 5:41 PM on May 17, 2012:

Can use the same command line flag for these too...

in src/addrman.cpp:None in 22251182f9 outdated

 302 | @@ -303,7 +303,8 @@ void CAddrMan::Good_(const CService &addr, int64 nTime)
 303 |      // TODO: maybe re-add the node, but for now, just bail out
 304 |      if (nUBucket == -1) return;
 305 |  
 306 | -    printf("Moving %s to tried\n", addr.ToString().c_str());
 307 | +    if (fDebug)
 308 | +        printf("Moving %s to tried\n", addr.ToString().c_str());

jgarzik commented at 5:22 PM on May 17, 2012:

this is infrequent, so who cares?

rebroad commented at 5:40 PM on May 17, 2012:

It's very frequent in my output.. Hmmm. Would you prefer another command line flag other than -debug were used for this?

in src/db.cpp:None in 22251182f9 outdated

 320 | @@ -320,6 +321,7 @@ void DBFlush(bool fShutdown)
 321 |              else
 322 |                  mi++;
 323 |          }
 324 | +        printf("DBFlush: After while loop (%s)%s %15"PRI64d"ms\n", fShutdown ? "true" : "false", fDbEnvInit ? "" : " db not started", GetTimeMillis() - nStart);

jgarzik commented at 5:22 PM on May 17, 2012:

ack

in src/init.cpp:None in 22251182f9 outdated

  75 | @@ -75,9 +76,10 @@ void Shutdown(void* parg)
  76 |      }
  77 |  }
  78 |  
  79 | -void HandleSIGTERM(int)
  80 | +void HandleSIGTERM(int signal)
  81 |  {
  82 |      fRequestShutdown = true;
  83 | +    printf("HandleSIGTERM(%d)\n", signal);

jgarzik commented at 5:23 PM on May 17, 2012:

not sure calling our printf infrastructure from a signal handler is wise

rebroad commented at 5:41 PM on May 17, 2012:

Why not? I've been testing this code now for 6 weeks without any problems.

in src/init.cpp:None in 22251182f9 outdated

 318 | @@ -315,6 +319,8 @@ bool AppInit2()
 319 |      fPrintToConsole = GetBoolArg("-printtoconsole");
 320 |      fPrintToDebugger = GetBoolArg("-printtodebugger");
 321 |      fLogTimestamps = GetBoolArg("-logtimestamps");
 322 | +    fQuietInitial = GetBoolArg("-quietinitial");
 323 | +    fLogPeers = GetBoolArg("-logpeers");

jgarzik commented at 5:23 PM on May 17, 2012:

at a minimum, these are new features that belong in separate commits, not a single commit entitled "improve debug.log output"

rebroad commented at 5:42 PM on May 17, 2012:

On one hand, you're right, but on the other, it's certainly a pain in the neck for me to have to rebase with these as separate commits, as they're usually needing manual intervention. Perhaps I'm not using git properly though....

in src/init.cpp:None in 22251182f9 outdated

 487 | @@ -481,7 +488,7 @@ bool AppInit2()
 488 |  
 489 |      //// debug print
 490 |      printf("mapBlockIndex.size() = %d\n",   mapBlockIndex.size());
 491 | -    printf("nBestHeight = %d\n",            nBestHeight);
 492 | +    //printf("nBestHeight = %d\n",            nBestHeight); // TMI

jgarzik commented at 5:24 PM on May 17, 2012:

huh?

rebroad commented at 5:44 PM on May 17, 2012:

That was commented out as 8 lines further up in the debug.log file that information is displayed there.

in src/irc.cpp:None in 22251182f9 outdated

 199 | @@ -200,7 +200,7 @@ void ThreadIRCSeed(void* parg)
 200 |      } catch (...) {
 201 |          PrintExceptionContinue(NULL, "ThreadIRCSeed()");
 202 |      }
 203 | -    printf("ThreadIRCSeed exiting\n");
 204 | +    printf("ThreadIRCSeed exited\n");

jgarzik commented at 5:25 PM on May 17, 2012:

all changes like this grammar change should have been in its own commit, separate from all other commits

rebroad commented at 5:38 PM on May 17, 2012:

ah, ok. separate commit, but same pull, do you mean?

Diapolo commented at 5:46 PM on May 17, 2012:

I would do string-changes / grammar changes in seperate pulls.

in src/irc.cpp:None in 22251182f9 outdated

 320 | @@ -321,7 +321,7 @@ void ThreadIRCSeed2(void* parg)
 321 |                  // index 7 is limited to 16 characters
 322 |                  // could get full length name at index 10, but would be different from join messages
 323 |                  strlcpy(pszName, vWords[7].c_str(), sizeof(pszName));
 324 | -                printf("IRC got who\n");
 325 | +                // printf("IRC got who\n");  // TMI

jgarzik commented at 5:25 PM on May 17, 2012:

even if it is TMI, we don't leave scattered bits of dead code all over the place

Diapolo commented at 5:30 PM on May 17, 2012:

What does TMI mean?

in src/main.cpp:None in 22251182f9 outdated

 487 | -            if (txin.prevout.IsNull())
 488 | -                return DoS(10, error("CTransaction::CheckTransaction() : prevout is null"));
 489 | +            if (txin.prevout.IsNull()) {
 490 | +                if (txnode && fLogPeers) printf("%s ", txnode->addr.ToString().c_str());
 491 | +                return DoS(10, error("checktx: %s prevout is null", hash.ToString().substr(0,10).c_str()));
 492 | +            }

jgarzik commented at 5:26 PM on May 17, 2012:

these checktx changes do look useful, but again... separate commit, not glommed together into a single "improve debug.log output" huge commit

rebroad commented at 5:43 PM on May 17, 2012:

Is there a particular easy way using git to break this up into smaller commits, or do I just take a backup, rewind, and add each one as a separate branch from upstream master?

Improve debug.log output.

Also, rename AlreadyAskedFor to AlreadyWaitingFor (makes more sense, as can cease waiting, but cannot stop having done a past thing.)

Only display peer if fLogPeers is set, for privacy purposes.

Conflicts:

	src/main.cpp

6dbd0199d2

rebroad closed this on May 29, 2012

rebroad deleted the branch on Dec 23, 2012

suprnurd referenced this in commit 0ecc7c61eb on Dec 5, 2017

lateminer referenced this in commit ec666ec8d8 on May 6, 2020

DrahtBot locked this on Sep 8, 2021