[test] Suppress test logging spam #10124

pull jnewbery wants to merge 1 commits into bitcoin:master from jnewbery:suppress_test_logging_spam changing 2 files +13 −3

jnewbery commented at 4:02 PM on March 30, 2017: member
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
in test/functional/test_framework/mininode.py:1771 in e2127a9d29 outdated
```
1767 | @@ -1768,7 +1768,7 @@ def got_message(self, message):
1768 |                  self.messagemap[b'ping'] = msg_ping_prebip31
1769 |          if self.last_sent + 30 * 60 < time.time():
1770 |              self.send_message(self.messagemap[b'ping']())
1771 | -        logger.debug("Received message from %s:%d: %s" % (self.dstaddr, self.dstport, repr(message)))
1772 | +        logger.debug("Received message from %s:%d: %.200s" % (self.dstaddr, self.dstport, repr(message)))
```
JeremyRubin commented at 5:38 PM on March 30, 2017:

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.

jnewbery commented at 6:31 PM on March 30, 2017:

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 commented at 5:38 PM on March 30, 2017: contributor

utack
fanquake added the label Tests on Mar 30, 2017
fanquake added the label Utils and libraries on Mar 31, 2017
jnewbery force-pushed on Mar 31, 2017
jnewbery force-pushed on Apr 3, 2017
laanwj commented at 4:08 PM on April 3, 2017: member

Needs rebase after #10123
jnewbery force-pushed on Apr 3, 2017
jnewbery commented at 4:43 PM on April 3, 2017: member

Rebased
sipa commented at 7:10 AM on April 4, 2017: member

Concept ACK

in test/functional/test_framework/mininode.py:1774 in b6c9a9a08b outdated

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

MarcoFalke commented at 8:03 AM on April 4, 2017:

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

jnewbery commented at 10:05 PM on April 4, 2017:

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

MarcoFalke commented at 8:03 AM on April 4, 2017: member

utACK b6c9a9a08bd58f53cbf2adbd58573348c63be79e

in test/functional/test_framework/mininode.py:1752 in 69700647b8 outdated

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

MarcoFalke commented at 10:26 PM on April 4, 2017:

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

jnewbery commented at 2:34 PM on April 5, 2017:

sure

jnewbery commented at 2:35 PM on April 5, 2017: member

@MarcoFalke nit addressed.

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

Reduce spammy test logging

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.

45ce471ab0

jnewbery force-pushed on Apr 8, 2017
jnewbery commented at 2:18 AM on April 8, 2017: member

commits squashed.
MarcoFalke merged this on Apr 8, 2017
MarcoFalke closed this on Apr 8, 2017
MarcoFalke referenced this in commit 88799ea1b1 on Apr 8, 2017
PastaPastaPasta referenced this in commit ecd3ad4520 on May 20, 2019
PastaPastaPasta referenced this in commit fd246a96ca on May 20, 2019
PastaPastaPasta referenced this in commit 16ca0f353a on May 21, 2019
PastaPastaPasta referenced this in commit da005b03f9 on May 22, 2019
PastaPastaPasta referenced this in commit 3d0e8ea242 on May 22, 2019
PastaPastaPasta referenced this in commit 6a310d0da9 on May 22, 2019
PastaPastaPasta referenced this in commit e08992e891 on May 22, 2019
PastaPastaPasta referenced this in commit 888e746f0c on May 23, 2019
UdjinM6 referenced this in commit 7ea034cd5e on May 23, 2019
PastaPastaPasta referenced this in commit 7c2985c326 on May 23, 2019
attilaaf referenced this in commit 90b86ad1dd on May 25, 2019
PastaPastaPasta referenced this in commit f893ac66ca on May 27, 2019
barrystyle referenced this in commit d5328834e1 on Jan 22, 2020
random-zebra referenced this in commit eb1ed66c2e on Apr 4, 2020
MarcoFalke locked this on Sep 8, 2021

Contributors

Labels

Linked (view graph)

#9424 Change LogAcceptCategory to use uint32_t rather than sets of strings.#10123 Allow debug logs to be excluded from specified component