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

• 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.

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

Tested ACK d7df43b202f2bbeba3d94e2bbc9a301141bfa62f

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)

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

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.

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)

@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?

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.

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?

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.

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.

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.

@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.

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.

needs rebase.

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

Tested ACK 32c0d6e