Skip to content

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

Merged
laanwj merged 1 commit intobitcoin:masterfrom
jnewbery:btutiltestlogging
Nov 2, 2016
Merged

Add logging to bitcoin-util-test.py#9023
laanwj merged 1 commit intobitcoin:masterfrom
jnewbery:btutiltestlogging

Conversation

@jnewbery
Copy link
Contributor

@jnewbery jnewbery 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
Copy link
Contributor

btcdrak commented Oct 26, 2016

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

maflcko
maflcko reviewed Oct 26, 2016
View reviewed changes
src/test/bctest.py Outdated
Copy link
Member

@maflcko maflcko Oct 26, 2016

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Any reason to use raise Exception instead of raise?

Copy link
Contributor Author

@jnewbery jnewbery Oct 26, 2016

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

@laanwj laanwj added the Tests label Oct 26, 2016
@btcdrak
Copy link
Contributor

btcdrak commented Oct 26, 2016

Tested ACK d7df43b202f2bbeba3d94e2bbc9a301141bfa62f

@laanwj
Copy link
Member

laanwj commented Oct 27, 2016 •
edited
Loading

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
Copy link
Contributor

btcdrak 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
Copy link
Member

laanwj 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
Copy link
Member

laanwj commented Oct 27, 2016 •
edited
Loading

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
Copy link
Contributor Author

jnewbery 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
Copy link
Member

laanwj 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
Copy link
Contributor Author

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

@jnewbery jnewbery mentioned this pull request Oct 27, 2016
Merged
@laanwj
Copy link
Member

laanwj commented Oct 27, 2016 •
edited
Loading

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
Copy link
Contributor Author

jnewbery 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
Copy link
Member

laanwj 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
Copy link
Contributor Author

jnewbery 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
Copy link
Member

laanwj 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
Copy link
Contributor

btcdrak commented Nov 2, 2016

needs rebase.

@jnewbery
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
Copy link
Contributor Author

jnewbery 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
Copy link
Member

laanwj commented Nov 2, 2016

Tested ACK 32c0d6e

@laanwj laanwj merged commit 32c0d6e into bitcoin:master Nov 2, 2016
laanwj added a commit that referenced this pull request Nov 2, 2016
@laanwj
Merge #9023: Add logging to bitcoin-util-test.py
774db92 
32c0d6e Add logging to bitcoin-util-test.py (jnewbery)
@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
@laanwj @codablock
Merge bitcoin#9023: Add logging to bitcoin-util-test.py
07f406f 
32c0d6e Add logging to bitcoin-util-test.py (jnewbery)
@dagurval dagurval mentioned this pull request Apr 27, 2018
Merged
andvgal pushed a commit to energicryptocurrency/gen2-energi that referenced this pull request Jan 6, 2019
@laanwj @andvgal
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
@laanwj @CryptoCentric
Merge bitcoin#9023: Add logging to bitcoin-util-test.py
f04d71c 
32c0d6e Add logging to bitcoin-util-test.py (jnewbery)
@str4d str4d mentioned this pull request Oct 28, 2020
Merged
zkbot added a commit to zcash/zcash that referenced this pull request Nov 9, 2020
@zkbot
Auto merge of #4835 - str4d:bctest-backports, r=str4d
bd5ff7c 
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
@bitcoin bitcoin locked as resolved and limited conversation to collaborators Sep 8, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.

Reviewers

1 more reviewer

@maflcko maflcko maflcko left review comments

Reviewers whose approvals may not affect merge requirements

Assignees

No one assigned

Labels

Tests

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

4 participants

@jnewbery @btcdrak @laanwj @maflcko