Add logging to bitcoin-util-test.py #9023

jnewbery · 2016-10-26T11:10:54Z

Use the python standard logging library
Run all tests and report all failing test-cases (rather than stop after one test case fails)
If output is different from expected output, log a contextual diff.

btcdrak · 2016-10-26T11:37:34Z

Very nice, I was just struggling with some failing tests and thinking about adding logging. Concept ACK, testing.

maflcko · 2016-10-26T11:39:48Z

src/test/bctest.py

+			outputData = open(testDir + "/" + outputFn).read()
+		except:
+			logging.error("Output file " + outputFn + " can not be opened")
+			raise Exception


Any reason to use raise Exception instead of raise?

You're right - raise is better. I've updated it.

btcdrak · 2016-10-26T15:18:01Z

Tested ACK d7df43b202f2bbeba3d94e2bbc9a301141bfa62f

laanwj · 2016-10-27T12:16:45Z

Concept ACK, but I think this makes the test too noisy in the passing case. Ideally tests are silent if nothing is wrong and noisy if they break.

Why not just print a diff when the comparison fails, and leave it at that? (in non-verbose mode)

btcdrak · 2016-10-27T12:26:13Z

After some chat with @laanwj can you make this silently pass tests unless --verbose is selected? But output failure cases by default without --verbose?

laanwj · 2016-10-27T12:39:26Z

Easiest way would be to move PASSED messages to the debug level:

diff --git a/src/test/bctest.py b/src/test/bctest.py
index e575b22..0e83284 100644
--- a/src/test/bctest.py
+++ b/src/test/bctest.py
@@ -67,7 +67,7 @@ def bctester(testDir, input_basename, buildenv):
        for testObj in input_data:
                try:
                        bctest(testDir, testObj, buildenv.exeext)
-                       logging.info("PASSED: " + testObj["description"])
+                       logging.debug("PASSED: " + testObj["description"])
                except:
                        logging.info("FAILED: " + testObj["description"])
                        failed_testcases.append(testObj["description"])

However -v doesn't seem to work here? Debug messages aren't printed.

laanwj · 2016-10-27T12:42:13Z

This helps, you're setting the log level twice.

diff --git a/src/test/bitcoin-util-test.py b/src/test/bitcoin-util-test.py
index 3bae55d..c72dc9f 100755
--- a/src/test/bitcoin-util-test.py
+++ b/src/test/bitcoin-util-test.py
@@ -35,12 +35,12 @@ if __name__ == '__main__':
     # Create logging handler
     ch = logging.StreamHandler(sys.stdout)
     if verbose:
-        ch.setLevel(logging.DEBUG)
+        level = logging.DEBUG
     else:
-        ch.setLevel(logging.ERROR)
+        level = logging.ERROR
     formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(message)s')
     ch.setFormatter(formatter)
     # Add the handlers to the logger
-    logging.basicConfig(level=logging.INFO, handlers=[ch])
+    logging.basicConfig(level=level, handlers=[ch])

     bctest.bctester(srcdir + "/test/data", "bitcoin-util-test.json", buildenv)

jnewbery · 2016-10-27T14:11:12Z

@laanwj - I believe the log level needs to be set once for the logger and once for the handler. See https://docs.python.org/3/howto/logging.html#logging-flow for how log levels are set in logging.

The intent was certainly that without verbose the behaviour would be:

failures are logged
successes are silent
a summary of failed testcases is printed at the end.

With verbose, both failure and success is logged along with a summary of results.

Here's my output when running with and without verbose for a single test failing:

NOT VERBOSE:

vagrant@vagrant-ubuntu-trusty-64:~/bitcoin/src$ python3 test/bitcoin-util-test.py --srcdir='.'
2016-10-27 14:07:31,584 - ERROR - Output data mismatch for txcreate1.json:
*** txcreate1.json
--- returned
***************
*** 1,6 ****
  {
      "txid": "f70f0d6c71416ed538e37549f430ab3665fee2437a42f10238c1bd490e782231",
!     "hash": "I'm a bad hash",
      "version": 1,
      "locktime": 0,
      "vin": [
--- 1,6 ----
  {
      "txid": "f70f0d6c71416ed538e37549f430ab3665fee2437a42f10238c1bd490e782231",
!     "hash": "f70f0d6c71416ed538e37549f430ab3665fee2437a42f10238c1bd490e782231",
      "version": 1,
      "locktime": 0,
      "vin": [

2016-10-27 14:07:31,688 - ERROR - FAILED TESTCASES: [Creates a new transaction with three inputs and two outputs (output in json)]

VERBOSE:

vagrant@vagrant-ubuntu-trusty-64:~/bitcoin/src$ python3 test/bitcoin-util-test.py --srcdir='.' --verbose
2016-10-27 14:07:26,766 - INFO - PASSED: Creates a blank transaction
2016-10-27 14:07:26,771 - INFO - PASSED: Creates a blank transaction (output in json)
2016-10-27 14:07:26,778 - INFO - PASSED: Creates a blank transaction when nothing is piped into bitcoin-tx
2016-10-27 14:07:26,785 - INFO - PASSED: Creates a blank transaction when nothing is piped into bitcoin-tx (output in json)
2016-10-27 14:07:26,791 - INFO - PASSED: Deletes a single input from a transaction
2016-10-27 14:07:26,797 - INFO - PASSED: Deletes a single input from a transaction (output in json)
2016-10-27 14:07:26,810 - INFO - PASSED: Attempts to delete an input with a bad index from a transaction. Expected to fail.
2016-10-27 14:07:26,818 - INFO - PASSED: Deletes a single output from a transaction
2016-10-27 14:07:26,828 - INFO - PASSED: Deletes a single output from a transaction (output in json)
2016-10-27 14:07:26,835 - INFO - PASSED: Attempts to delete an output with a bad index from a transaction. Expected to fail.
2016-10-27 14:07:26,840 - INFO - PASSED: Adds an nlocktime to a transaction
2016-10-27 14:07:26,847 - INFO - PASSED: Adds an nlocktime to a transaction (output in json)
2016-10-27 14:07:26,855 - INFO - PASSED: Creates a new transaction with three inputs and two outputs
2016-10-27 14:07:26,865 - ERROR - Output data mismatch for txcreate1.json:
*** txcreate1.json
--- returned
***************
*** 1,6 ****
  {
      "txid": "f70f0d6c71416ed538e37549f430ab3665fee2437a42f10238c1bd490e782231",
!     "hash": "I'm a bad hash",
      "version": 1,
      "locktime": 0,
      "vin": [
--- 1,6 ----
  {
      "txid": "f70f0d6c71416ed538e37549f430ab3665fee2437a42f10238c1bd490e782231",
!     "hash": "f70f0d6c71416ed538e37549f430ab3665fee2437a42f10238c1bd490e782231",
      "version": 1,
      "locktime": 0,
      "vin": [

2016-10-27 14:07:26,869 - INFO - FAILED: Creates a new transaction with three inputs and two outputs (output in json)
2016-10-27 14:07:26,877 - INFO - PASSED: Creates a new transaction with a single empty output script
2016-10-27 14:07:26,884 - INFO - PASSED: Creates a new transaction with a single empty output script (output in json)
2016-10-27 14:07:26,912 - INFO - PASSED: Creates a new transaction with a single input and a single output, and then signs the transaction
2016-10-27 14:07:26,934 - INFO - PASSED: Creates a new transaction with a single input and a single output, and then signs the transaction (output in json)
2016-10-27 14:07:26,940 - INFO - PASSED: Attempts to create a new transaction with one input and an output with malformed hex data. Expected to fail
2016-10-27 14:07:26,945 - INFO - PASSED: Attempts to create a new transaction with one input and an output with no value and malformed hex data. Expected to fail
2016-10-27 14:07:26,955 - INFO - PASSED: Creates a new transaction with one input, one address output and one data output
2016-10-27 14:07:26,962 - INFO - PASSED: Creates a new transaction with one input, one address output and one data output (output in json)
2016-10-27 14:07:26,968 - INFO - PASSED: Creates a new transaction with one input, one address output and one data (zero value) output
2016-10-27 14:07:26,974 - INFO - PASSED: Creates a new transaction with one input, one address output and one data (zero value) output (output in json)
2016-10-27 14:07:26,982 - INFO - PASSED: Creates a new transaction with one input with sequence number and one address output
2016-10-27 14:07:26,991 - INFO - PASSED: Creates a new transaction with one input with sequence number and one address output (output in json)
2016-10-27 14:07:26,999 - INFO - PASSED: Adds a new input with sequence number to a transaction
2016-10-27 14:07:27,007 - INFO - PASSED: Adds a new input with sequence number to a transaction (output in json)
2016-10-27 14:07:27,007 - ERROR - FAILED TESTCASES: [Creates a new transaction with three inputs and two outputs (output in json)]

with automated runs (make check) verbose should not be set.

Are you seeing something different?

laanwj · 2016-10-27T14:39:58Z

Ah I'm apparently testing with python, the default interpreter in the #! line (which is python2, not python3 on Ubuntu 16.04). In any case the -v flag didn't do anything, until applying the second patch.

The first patch doesn't seem to be necessary. Indeed the log level for non-verbose is set to ERROR so the INFO messages should already not get logged.

Without that, I always get verbose behavior:

$ PYTHONPATH=./test $HOME/projects/bitcoin/bitcoin/src/test/bitcoin-util-test.py -s $HOME/projects/bitcoin/bitcoin/src
INFO:root:PASSED: Creates a blank transaction
INFO:root:PASSED: Creates a blank transaction (output in json)
INFO:root:PASSED: Creates a blank transaction when nothing is piped into bitcoin-tx
INFO:root:PASSED: Creates a blank transaction when nothing is piped into bitcoin-tx (output in json)
INFO:root:PASSED: Deletes a single input from a transaction
INFO:root:PASSED: Deletes a single input from a transaction (output in json)
INFO:root:PASSED: Attempts to delete an input with a bad index from a transaction. Expected to fail.
INFO:root:PASSED: Deletes a single output from a transaction
INFO:root:PASSED: Deletes a single output from a transaction (output in json)
INFO:root:PASSED: Attempts to delete an output with a bad index from a transaction. Expected to fail.
INFO:root:PASSED: Adds an nlocktime to a transaction
INFO:root:PASSED: Adds an nlocktime to a transaction (output in json)
INFO:root:PASSED: Creates a new transaction with three inputs and two outputs
INFO:root:PASSED: Creates a new transaction with three inputs and two outputs (output in json)
INFO:root:PASSED: Creates a new transaction with a single empty output script
INFO:root:PASSED: Creates a new transaction with a single empty output script (output in json)
INFO:root:PASSED: Creates a new transaction with a single input and a single output, and then signs the transaction
INFO:root:PASSED: Creates a new transaction with a single input and a single output, and then signs the transaction (output in json)
INFO:root:PASSED: Attempts to create a new transaction with one input and an output with malformed hex data. Expected to fail
INFO:root:PASSED: Attempts to create a new transaction with one input and an output with no value and malformed hex data. Expected to fail
INFO:root:PASSED: Creates a new transaction with one input, one address output and one data output
INFO:root:PASSED: Creates a new transaction with one input, one address output and one data output (output in json)
INFO:root:PASSED: Creates a new transaction with one input, one address output and one data (zero value) output
INFO:root:PASSED: Creates a new transaction with one input, one address output and one data (zero value) output (output in json)
INFO:root:PASSED: Creates a new transaction with one input with sequence number and one address output
INFO:root:PASSED: Creates a new transaction with one input with sequence number and one address output (output in json)
INFO:root:PASSED: Adds a new input with sequence number to a transaction
INFO:root:PASSED: Adds a new input with sequence number to a transaction (output in json)

With python3 I get the behavior you describe.

jnewbery · 2016-10-27T15:09:33Z

Oh, that makes sense. Are you happy for me to bump bitcoin-util-test.py and bctest.py to python3 as part of this PR?

laanwj · 2016-10-27T15:32:34Z

Right now, all the scripts that are called by the build system work in python 2 and python 3. It seems it is quite easy to keep Python2 compatibility here (I even suggested a fix). But I don't care deeply.

jnewbery · 2016-10-28T14:55:57Z

The qa python scripts were changed to use python3 in #7737 , so it seems reasonable to me to also move bitcoin-test-util to python3.

laanwj · 2016-10-28T16:10:00Z

The python scripts that are not invoked by the build system were changed to be Python 3 only. For example qa/rpctests, and contrib/devtools. This one is used by make check which would ideally keep working with python 2.
I don't understand why you don't just apply the small patch I gave above to make it work with python 2 again.

jnewbery · 2016-10-31T15:21:24Z

@laanwj - I went ahead with changing this to Python3 because your last comment was that you didn't care deeply :)

I can edit bitcoin-util-test.py again to make it compatible with Python 2 again, but I don't like your patch. The reason that the -v flag wasn't working with Python 2 is that the stream handler ch is being ignored. On line 44:

logging.basicConfig(level=logging.INFO, handlers=[ch])

basicConfig() takes a named handlers argument. This argument was added in Python 3.3 (https://docs.python.org/3.7/library/logging.html#logging.basicConfig), so in Python2 basicConfig will create a new stream handler to handle the logging. Your patch works because you change the logger level to DEBUG, and the default handler will have levelNOTSET.

The outcome is that the ch stream logger is unused when this is run in Python 2 (that's why the formatting isn't correct for the logs). I think that makes the code confusing since we're setting up a handler and then not using it.

I'd personally prefer to specify Python 3 to avoid having to think about Python2/3 compatibility issues like this. However, if you think there's a good reason to maintain Python 2 compatibility, I'll spend some more time to come up with a proper fix.

Let me know what you think.

Note: travis build has failed due to unrelated intermittent failure in p2p-compactblocks.py. I expect rerunning the travis build will succeed.

laanwj · 2016-10-31T15:53:09Z

I don't care deeply, that doesn't mean no one else does. To be clear: breaking python 2 compatibility will possibly result in long discussions (as it means deprecating Python 2 support for "make check"), which have to be done on a higher level than in this PR only, whereas maintaining it means this can be merged fairly quickly.

btcdrak · 2016-11-02T10:49:23Z

needs rebase.

- Use the python standard logging library - Run all tests and report all failing test-cases (rather than stop after one test case fails) - If output is different from expected output, log a contextual diff.

jnewbery · 2016-11-02T18:19:58Z

New squashed commit does the following:

rebased
Python3 compatibility restored
made logging compatible with Python2. Execution should be the same when running under Python2 and Python3

laanwj · 2016-11-02T19:52:46Z

Tested ACK 32c0d6e

32c0d6e Add logging to bitcoin-util-test.py (jnewbery)

bitcoin-util-test.py backports Cherry-picked from the following upstream PRs: - bitcoin/bitcoin#8829 - bitcoin/bitcoin#8830 - bitcoin/bitcoin#8836 - bitcoin/bitcoin#8881 - bitcoin/bitcoin#9032 - bitcoin/bitcoin#9023 - bitcoin/bitcoin#9069 - bitcoin/bitcoin#9945

maflcko reviewed Oct 26, 2016

View reviewed changes

laanwj added the Tests label Oct 26, 2016

jnewbery force-pushed the btutiltestlogging branch from d7df43b to 57cae38 Compare October 26, 2016 13:52

jnewbery mentioned this pull request Oct 27, 2016

test: Add format-dependent comparison to bctest #9032

Merged

jnewbery force-pushed the btutiltestlogging branch from 465c819 to 6be57b0 Compare October 28, 2016 14:54

jnewbery force-pushed the btutiltestlogging branch from 6be57b0 to f2eefd6 Compare November 2, 2016 18:05

Add logging to bitcoin-util-test.py

32c0d6e

- Use the python standard logging library - Run all tests and report all failing test-cases (rather than stop after one test case fails) - If output is different from expected output, log a contextual diff.

jnewbery force-pushed the btutiltestlogging branch from f2eefd6 to 32c0d6e Compare November 2, 2016 18:17

laanwj merged commit 32c0d6e into bitcoin:master Nov 2, 2016

laanwj added a commit that referenced this pull request Nov 2, 2016

Merge #9023: Add logging to bitcoin-util-test.py

774db92

32c0d6e Add logging to bitcoin-util-test.py (jnewbery)

jnewbery deleted the btutiltestlogging branch November 4, 2016 08:36

codablock pushed a commit to codablock/dash that referenced this pull request Jan 13, 2018

Merge bitcoin#9023: Add logging to bitcoin-util-test.py

07f406f

32c0d6e Add logging to bitcoin-util-test.py (jnewbery)

dagurval mentioned this pull request Apr 27, 2018

bitcoin-tx JSON tests + test util improvements bitcoinxt/bitcoinxt#404

Merged

andvgal pushed a commit to energicryptocurrency/gen2-energi that referenced this pull request Jan 6, 2019

Merge bitcoin#9023: Add logging to bitcoin-util-test.py

32aae41

32c0d6e Add logging to bitcoin-util-test.py (jnewbery)

CryptoCentric pushed a commit to absolute-community/absolute that referenced this pull request Feb 15, 2019

Merge bitcoin#9023: Add logging to bitcoin-util-test.py

f04d71c

32c0d6e Add logging to bitcoin-util-test.py (jnewbery)

str4d mentioned this pull request Oct 28, 2020

bitcoin-util-test.py backports zcash/zcash#4835

Merged

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

Add logging to bitcoin-util-test.py #9023

Add logging to bitcoin-util-test.py #9023

Uh oh!

Conversation

jnewbery commented Oct 26, 2016

Uh oh!

btcdrak commented Oct 26, 2016

Uh oh!

maflcko Oct 26, 2016

Choose a reason for hiding this comment

Uh oh!

jnewbery Oct 26, 2016

Choose a reason for hiding this comment

Uh oh!

btcdrak commented Oct 26, 2016

Uh oh!

laanwj commented Oct 27, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

btcdrak commented Oct 27, 2016

Uh oh!

laanwj commented Oct 27, 2016

Uh oh!

laanwj commented Oct 27, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jnewbery commented Oct 27, 2016

Uh oh!

laanwj commented Oct 27, 2016

Uh oh!

jnewbery commented Oct 27, 2016

Uh oh!

laanwj commented Oct 27, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jnewbery commented Oct 28, 2016

Uh oh!

laanwj commented Oct 28, 2016

Uh oh!

jnewbery commented Oct 31, 2016

Uh oh!

laanwj commented Oct 31, 2016

Uh oh!

btcdrak commented Nov 2, 2016

Uh oh!

jnewbery commented Nov 2, 2016

Uh oh!

laanwj commented Nov 2, 2016

Uh oh!

Uh oh!

laanwj commented Oct 27, 2016 •

edited

Loading

laanwj commented Oct 27, 2016 •

edited

Loading

laanwj commented Oct 27, 2016 •

edited

Loading