Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Merged
merged 1 commit into from Nov 2, 2016

Conversation

@jnewbery
Copy link
Member

commented Oct 26, 2016

  • 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

This comment has been minimized.

Copy link
Member

commented Oct 26, 2016

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

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

This comment has been minimized.

Copy link
@MarcoFalke

MarcoFalke Oct 26, 2016

Member

Any reason to use raise Exception instead of raise?

This comment has been minimized.

Copy link
@jnewbery

jnewbery Oct 26, 2016

Author Member

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

@laanwj laanwj added the Tests label Oct 26, 2016

@jnewbery jnewbery force-pushed the jnewbery:btutiltestlogging branch Oct 26, 2016

@btcdrak

This comment has been minimized.

Copy link
Member

commented Oct 26, 2016

Tested ACK d7df43b202f2bbeba3d94e2bbc9a301141bfa62f

@laanwj

This comment has been minimized.

Copy link
Member

commented Oct 27, 2016

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

This comment has been minimized.

Copy link
Member

commented Oct 27, 2016

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

This comment has been minimized.

Copy link
Member

commented Oct 27, 2016

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

This comment has been minimized.

Copy link
Member

commented Oct 27, 2016

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

This comment has been minimized.

Copy link
Member Author

commented Oct 27, 2016

@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

This comment has been minimized.

Copy link
Member

commented Oct 27, 2016

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

This comment has been minimized.

Copy link
Member Author

commented Oct 27, 2016

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

This comment has been minimized.

Copy link
Member

commented Oct 27, 2016

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 jnewbery force-pushed the jnewbery:btutiltestlogging branch Oct 28, 2016

@jnewbery

This comment has been minimized.

Copy link
Member Author

commented Oct 28, 2016

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

This comment has been minimized.

Copy link
Member

commented Oct 28, 2016

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

This comment has been minimized.

Copy link
Member Author

commented Oct 31, 2016

@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

This comment has been minimized.

Copy link
Member

commented Oct 31, 2016

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

This comment has been minimized.

Copy link
Member

commented Nov 2, 2016

needs rebase.

@jnewbery jnewbery force-pushed the jnewbery:btutiltestlogging branch Nov 2, 2016

Add logging to bitcoin-util-test.py
- 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 jnewbery force-pushed the jnewbery:btutiltestlogging branch to 32c0d6e Nov 2, 2016

@jnewbery

This comment has been minimized.

Copy link
Member Author

commented Nov 2, 2016

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

This comment has been minimized.

Copy link
Member

commented Nov 2, 2016

Tested ACK 32c0d6e

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

1 check passed

continuous-integration/travis-ci/pr The Travis CI build passed
Details
laanwj added a commit that referenced this pull request Nov 2, 2016
Merge #9023: Add logging to bitcoin-util-test.py
32c0d6e Add logging to bitcoin-util-test.py (jnewbery)

@jnewbery jnewbery deleted the jnewbery:btutiltestlogging branch Nov 4, 2016

codablock added a commit to codablock/dash that referenced this pull request Jan 13, 2018
Merge bitcoin#9023: Add logging to bitcoin-util-test.py
32c0d6e Add logging to bitcoin-util-test.py (jnewbery)
andvgal added a commit to energicryptocurrency/energi that referenced this pull request Jan 6, 2019
Merge bitcoin#9023: Add logging to bitcoin-util-test.py
32c0d6e Add logging to bitcoin-util-test.py (jnewbery)
CryptoCentric added a commit to absolute-community/absolute that referenced this pull request Feb 15, 2019
Merge bitcoin#9023: Add logging to bitcoin-util-test.py
32c0d6e Add logging to bitcoin-util-test.py (jnewbery)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
4 participants
You can’t perform that action at this time.