[test] Suppress test logging spam #10124

jnewbery · 2017-03-30T16:02:30Z

EDIT2: reimplemented on top of #10123 now that #9424 is merged. This PR is now ready for review. Only the second commit is to be reviewed. The first commit is #10123

~~EDIT: reduced scope of this PR. I'm closing #10123 until #9424 is merged, but that shouldn't block reducing the test_framework log spam~~

This commit reduces spammy logging by the test framework and the
bitcoind instances in a test run:

truncate logging send/receive message in mininode to 200 characters.
mininode was previously logging the entire message sent received, which
can be up to 1MB for a full block.
exclude logging for leveldb and libevent in the bitcoind instances

requires #10123

JeremyRubin · 2017-03-30T17:38:32Z

test/functional/test_framework/mininode.py

@@ -1768,7 +1768,7 @@ def got_message(self, message):
                self.messagemap[b'ping'] = msg_ping_prebip31
        if self.last_sent + 30 * 60 < time.time():
            self.send_message(self.messagemap[b'ping']())
-        logger.debug("Received message from %s:%d: %s" % (self.dstaddr, self.dstport, repr(message)))
+        logger.debug("Received message from %s:%d: %.200s" % (self.dstaddr, self.dstport, repr(message)))


200 seems a bit small, and I'd imagine if we get a big error we don't expect we'd want to see it all? Maybe a slightly better way to do it is to filter on message type -- can you detect things that are big that we don't really want, e.g. messgae.startswith('bigmsgstartswith')?

also I prefer doing repr(message)[:200] than format string hacking as I always have to re-read format string rules to remember what they do.

Yes, we could do something more intelligent here, but I think this is at least an improvement on current behaviour. At the moment, a test like pruning.py , which sends hundreds of full blocks, will result in a log file that is GBs in size.

I can't think of a way to detect things that we don't want. A tx message could be up to 1MB, so should we filter them all out? How about block messages? I think the best we can do is truncate everything. Why 200 bytes? Because it seemed to me that 200 bytes would cover the most important information in the message, but I'm happy to bump it up a bit if you think that'd be useful.

I've changed the string formatting to a string slice to truncate the log as suggested.

JeremyRubin · 2017-03-30T17:38:52Z

utack

laanwj · 2017-04-03T16:08:42Z

Needs rebase after #10123

jnewbery · 2017-04-03T16:43:36Z

Rebased

sipa · 2017-04-04T07:10:21Z

Concept ACK

maflcko

utACK b6c9a9a08bd58f53cbf2adbd58573348c63be79e

maflcko · 2017-04-04T08:03:11Z

test/functional/test_framework/mininode.py

@@ -1771,7 +1771,7 @@ def got_message(self, message):
                self.messagemap[b'ping'] = msg_ping_prebip31
        if self.last_sent + 30 * 60 < time.time():
            self.send_message(self.messagemap[b'ping']())
-        logger.debug("Received message from %s:%d: %s" % (self.dstaddr, self.dstport, repr(message)))
+        logger.debug("Received message from %s:%d: %s" % (self.dstaddr, self.dstport, repr(message)[:500]))


Maybe indicate with three dots, that the message is truncated?

I've added this in the latest fixup commit. I also added a _log_message() method to avoid code duplication.

maflcko · 2017-04-04T22:26:43Z

test/functional/test_framework/mininode.py

@@ -1749,7 +1749,7 @@ def got_data(self):
    def send_message(self, message, pushbuf=False):
        if self.state != "connected" and not pushbuf:
            raise IOError('Not connected, no pushbuf')
-        logger.debug("Send message to %s:%d: %s" % (self.dstaddr, self.dstport, repr(message)[:500]))
+        self._log_message(True, message)


nit: Instead of a unnamed boolean, you could pass in the string "Sent" or "Received" directly?

jnewbery · 2017-04-05T14:35:08Z

@MarcoFalke nit addressed.

Let me know if you're happy for merge and I'll squash the fixup commits.

This commit reduces spammy logging by the test framework. It truncates logging send/receive message in mininode to 500 characters. mininode was previously logging the entire message sent received, which can be up to 1MB for a full block.

jnewbery · 2017-04-08T02:18:00Z

commits squashed.

45ce471 Reduce spammy test logging (John Newbery) Tree-SHA512: 64b2ce29fb62a4e738840bbaf93563559451c2ef078ba66ecfc1dbe34adefea61ad2ad2d768444cb2e0b30cb3cbe47e38ed818d4c91f7723a3d1ba9fdd0043f9

0a85445 [Core] Add -debugexclude option (random-zebra) Pull request description: Implemented on top of: - [x] #1449 - [x] #1437 Backports bitcoin#10123 > setting `-debug` can lead to very noisy debug.logs with subcomponents filling up the log file. See for example https://travis-ci.org/bitcoin/bitcoin/jobs/216767286 where there are hundreds of libevent debug logs. This commit adds an option to exclude certain components from debug logging. The usage is: ``` pivxd -debug -debugexclude=<component1> -debugexclude=<component2> ... ``` This finally reduces spammy logs in the functional tests debug, due to libevent and leveldb (bitcoin#10124 was already included backporting the test suite). ACKs for top commit: furszy: Code looking good, utACK 0a85445 . Fuzzbawls: ACK 0a85445 Tree-SHA512: 6ccbe275ab11f3e1739ed117e49db0a2e56db345287cddc7cc18fc1131d7800d0f08a7e93005f70cf45ed8e340580f91c3017532bd2ea28fedb5735409ae068b

JeremyRubin reviewed Mar 30, 2017

View reviewed changes

fanquake added Tests Utils/log/libs labels Mar 30, 2017

jnewbery force-pushed the suppress_test_logging_spam branch 2 times, most recently from 5cf6204 to 90ad293 Compare April 3, 2017 00:06

jnewbery force-pushed the suppress_test_logging_spam branch from 90ad293 to b6c9a9a Compare April 3, 2017 16:43

maflcko reviewed Apr 4, 2017

View reviewed changes

Reduce spammy test logging

45ce471

This commit reduces spammy logging by the test framework. It truncates logging send/receive message in mininode to 500 characters. mininode was previously logging the entire message sent received, which can be up to 1MB for a full block.

jnewbery force-pushed the suppress_test_logging_spam branch from c1ec681 to 45ce471 Compare April 8, 2017 02:17

maflcko merged commit 45ce471 into bitcoin:master Apr 8, 2017

dagurval mentioned this pull request Mar 7, 2018

Reduce noise in QA logs bitcoinxt/bitcoinxt#354

Merged

random-zebra mentioned this pull request Mar 20, 2020

[Core] Add -debugexclude option PIVX-Project/PIVX#1439

Merged

2 tasks

bitcoin locked as resolved and limited conversation to collaborators Sep 8, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

[test] Suppress test logging spam #10124

[test] Suppress test logging spam #10124

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

[test] Suppress test logging spam #10124

[test] Suppress test logging spam #10124

Uh oh!

Conversation

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!