[qa] Add logging to test_framework.py #9768

jnewbery · 2017-02-15T17:48:13Z

This is a WIP PR. Comments and feedback on the overall approach welcomed!

(For an overview of python's logging module and terms, see https://docs.python.org/3/library/logging.html and https://docs.python.org/3/howto/logging.html)

This PR adds logging to the test-framwork.py module. The "TestFramework" logger is added as a member of the BitcoinTestFramework class, and two handlers are attached to the logger:

a StreamHandler() which outputs ERROR and higher level records to stderr.
a FileHandler() which outputs all log records to a new test_framework.log file in the temporary test directory.

Test scripts and helper modules can log to the same Logger so there's a single log output:

Individual test scripts can log to "TestFramework" by calling self.log.[debug|info|warning|error|critical|exception]().
Helper modules should log to child Loggers such as "TestFramework.mininode" or "TestFramework.authproxy", which will result in log records being propagated up to the "TestFramework" Logger.

I've added examples of how individual scripts and helper modules should log events in p2p-segwit.py and mininode.py.

The eventual goal is to remove all print() calls and replace them with logging.

A few notes on the implementation:

a new --loglevel parameter can be used to log lower level records to the console, for example --loglevel=DEBUG will emit all log records to the console.
the date format of test_framework.log is the same as bitcoind's debug.log. It should be trivial to interleave test_framework.log with the various nodeX/debug.log files for a global view of what's happening during the test.
this should have no interaction with the existing --tracerpc parameter

laanwj · 2017-02-16T08:42:04Z

If you're working on custom logging stuff anyway: what would be really nice is something that would queue up debug messages, then print them only if the test fails. This lowers the amount of spam in the Travis log in the good case, and gives full troubleshooting information in the bad case (when you need it).

jnewbery · 2017-02-16T20:15:15Z

@laanwj done: #9780

ryanofsky · 2017-02-16T21:42:11Z

qa/rpc-tests/test_framework/test_framework.py

                os.rmdir(self.options.root)
        else:
-            print("Not cleaning up dir %s" % self.options.tmpdir)
+            self.log.info("Not cleaning up dir %s" % self.options.tmpdir)


Would upgrade this to a warning, since this is leaving files behind. Also this is a really useful print to see on the console when a test fails.

good point. Fixed.

ryanofsky · 2017-02-16T21:48:47Z

qa/rpc-tests/test_framework/test_framework.py

                          help="Directory for caching pregenerated datadirs")
        parser.add_option("--tmpdir", dest="tmpdir", default=tempfile.mkdtemp(prefix="test"),
                          help="Root directory for datadirs")
+        parser.add_option("--loglevel", dest="loglevel", default="ERROR",


You should say something about test_framework.log and console logging in the tests' --help output.

What you wrote in the commit message is good, but obviously no one is going to see if it is just in this commit message.

Thanks. Updated.

ryanofsky · 2017-02-16T21:50:05Z

qa/rpc-tests/test_framework/test_framework.py

        except JSONRPCException as e:
-            print("JSONRPC error: "+e.error['message'])
-            traceback.print_tb(sys.exc_info()[2])
+            self.log.exception("JSONRPC error: "+e.error['message'])


Should stop trying to print e here and below because log.exception already formats and prints the exception and stack trace: https://docs.python.org/3/library/logging.html#logging.Logger.exception. It's not helpful to see same information printed multiple times and in inconsistent ways.

Yep, good catch.

ryanofsky · 2017-02-16T21:53:07Z

qa/rpc-tests/test_framework/test_framework.py

        parser.add_option("--tmpdir", dest="tmpdir", default=tempfile.mkdtemp(prefix="test"),
                          help="Root directory for datadirs")
+        parser.add_option("--loglevel", dest="loglevel", default="ERROR",
+                          help="log events at this level and higher to the console")


Can you list what the log levels are? At least should probably mention that passing --loglevel=0 will show complete log output.

ryanofsky · 2017-02-16T22:07:13Z

qa/rpc-tests/test_framework/test_framework.py

+    def start_logging(self):
+        # Add logger and logging handlers
+        self.log = logging.getLogger('TestFramework')
+        self.log.setLevel(logging.DEBUG)


I think you're better off dropping this call. The default debug level seems to be 0, and the value of DEBUG is 10 so this potentially throws away logs.

Also would drop the 3 other setLevel(logging.DEBUG) calls below.

I think DEBUG is good here. We shouldn't encourage people to log messages at custom levels (ie not one of debug, info, warning, error and critical), and we especially shouldn't encourage people to log at a level lower than DEBUG.

I think DEBUG is good here. We shouldn't encourage people to log messages at custom levels (ie not one of debug, info, warning, error and critical), and we especially shouldn't encourage people to log at a level lower than DEBUG.

Actually setting DEBUG seems to be needed here in order to be able to see debug messages at all, otherwise python seems to fall back to root logger level which is WARNING.

Still I would consider dropping the "fh.setLevel()" call below. Having that call seems less like "not encouraging" people to log messages at custom levels, and more like going out of our way to punish and confuse them.

I still don't agree. logging at non-standard levels is harder (you need to call self.log.log(lvl, message) rather than self.log.debug(message) or similar). Why would anyone want do that, and why would we want to allow people to add confusing logging levels to the test cases?

ryanofsky · 2017-02-16T22:08:37Z

qa/rpc-tests/test_framework/test_framework.py

+        fh.setLevel(logging.DEBUG)
+        # Create console handler to log messages to stderr. By default this logs only error messages, but can be configured with --loglevel.
+        ch = logging.StreamHandler()
+        console_log_level = getattr(logging, self.options.loglevel.upper(), None)


Calling getattr doesn't seem to be necessary, the documentation says setLevel already accepts a string:
https://docs.python.org/3/library/logging.html#logging.Handler.setLevel. Maybe upper() is still useful though.

Agree. I was following the Python 'logging how to' guide here: https://docs.python.org/3/howto/logging.html#logging-to-a-file which uses getattr(). I guess that was written before 3.2, which is when setlevel() was updated to take a string argument.

I've tested the logging module and:

we do need to use upper() to set the log levels to uppercase

calling with an invalid string causes logging to raise a helpful exception (I was worried that it might fail silently).

So calling setlevel directly with self.options.loglevel.upper() is better.

ryanofsky · 2017-02-16T22:10:40Z

qa/rpc-tests/test_framework/test_framework.py

+            rpc_handler = logging.StreamHandler()
+            rpc_handler.setLevel(logging.DEBUG)
+            rpc_logger.addHandler(rpc_handler)
+            rpc_logger.debug("debug")


Junk lines?

yes. Junk lines from when I was testing this. Thanks. Removed.

ryanofsky · 2017-02-17T11:12:38Z

utACK 3e7ed8c

jnewbery · 2017-02-17T21:45:11Z

@ryanofsky thanks for the great feedback. I'm going to hold back on making any changes until I get some more concept ACKs/NACKs. I want to make sure people are happy going in this direction before I spend any time addressing review comments.

jnewbery · 2017-02-22T01:27:49Z

@MarcoFalke @laanwj @jonasschnelli @sdaftuar you're the most active contributors to the qa directory. Can you have a quick look and give me a concept ACK/NACK so I know whether to continue in this direction.

No rush. Obviously you're all busy with the 0.14 release.

sdaftuar · 2017-02-27T18:16:38Z

Concept ACK.

I haven't reviewed this PR in detail yet, but what I'd find useful is if the default behavior when running a single test locally was to print all log messages to the console, and only suppress log messages when running the tests through the rpc-tests.py script.

jnewbery · 2017-02-28T16:29:02Z

@sdaftuar the eventual aim will be to add a lot more low-level logging (eg logging when every p2p message is sent or received on the mininode connection). Those low-level logs will always be saved to test_framework.log, but by default are not printed to the console. If the user want low-level logs printed to console, they can specify --loglevel when running the script.

jnewbery · 2017-03-06T19:13:00Z

I've addressed @ryanofsky's review comments and repushed. A few updates since I opened this PR:

microsecond debug logging is now set by default on all test nodes. I've removed all places in the test code where debugging is set manually, since there's no reason not to use debug logging in these test cases.
I've added logging to the test_framework submodules
I've replaced print functions in the individual test-cases with logging calls

I've been running with this patch set locally for some time, together with a tool to interleave test_framwork logs with individual node logs. It makes troubleshooting testcases a lot easier since I have a global view of everything that's happening in the test case (ie I can see messages being sent in by the test framework and then received by the node).

I believe this is ready for merge, but any further review comments are welcomed.

ryanofsky

ACK 3b336aba4ef250868d6f3dc2bf741b0bbf621d39 assuming travis tests will be fixed.

ryanofsky · 2017-03-06T19:23:11Z

qa/rpc-tests/test_framework/test_framework.py

Should move the os.makedirs, and self.start_logging calls above the try: block, so error information won't be lost if these calls fail for some reason.

Good idea. I needed to put start_logging() below the os.makedirs() call, but you're right that this should be outside the large try/except block. I've now moved them both up.

ryanofsky · 2017-03-06T19:24:32Z

qa/rpc-tests/test_framework/test_framework.py

This should be changed to error instead of warning, to avoid potential for silent errors slipping through (even though in most cases, an error probably did print previously).

Also, I think it would be good for this message to mention the temp directory path (or alternately the path to test_framework.log), since it is no longer printed by default and is a piece of information you probably need to understand what happened.

Agree. Done both.

ryanofsky · 2017-03-06T19:46:29Z

qa/rpc-tests/test_framework/test_framework.py

Maybe I missed some discussion, but why is the default level error instead of debug or warning? I can understand disabling debug output by default when running pull-tester. But I run individual tests from the command line every day, and I can't remember a time when I've ever wanted to do this without seeing output.

If we have make error the default, can we at least support abbreviating "--loglevel=" as "-l", and allow passing integer log levels? This way it'd be possible to see debug output with -l0 instead of --loglevel=debug

Also would note that even the default level for the root python logger is warning, not error.

You're right. This should be INFO by default. DEBUG emits way too much to the console to be the default.

pull-tester diverts stdout from the subtests, so there's no output to console at all.

--loglevel now accepts ints as well as the named strings and can be specified with the short option -l

ryanofsky · 2017-03-06T20:21:53Z

qa/rpc-tests/test_framework/test_framework.py

Would be nice to support integer debug levels for less verbose command line usage. Maybe setLevel(int(self.options.loglevel) if self.options.loglevel.isdigit() else self.options.loglevel.upper()).

Yep. Good idea. Done (although I've split this over two lines for readability).

ryanofsky · 2017-03-06T20:33:46Z

qa/rpc-tests/bip68-sequence.py

Why drop mention of previous versions? Also, it seems like without this qualification, maybe the word "always" should be dropped too.

Because I previously thought that it was a bug that Core v0.13 (and a few earlier versions) always relayed v2 transactions - hence the 'with current versions' comment. See #9739 for the discussion. Whether or not it's a bug is moot now, and I think the 'with current verions' comment doesn't clarify.

'always' here means 'both before and after BIP 68 activation'.

ryanofsky · 2017-03-06T20:35:13Z

qa/rpc-tests/bip68-sequence.py

Probably best to remove trailing and prefix \n here and in other logging lines. (There seem to be 4-5 other occurrances in this PR.)

Thanks. Done.

ryanofsky · 2017-03-06T20:40:50Z

qa/rpc-tests/test_framework/comptool.py

Should be logging.getLogger. This is causing travis errors.

Yep. My mistake. Fixed.

ryanofsky · 2017-03-06T21:17:46Z

qa/rpc-tests/test_framework/test_framework.py

+    def start_logging(self):
+        # Add logger and logging handlers
+        self.log = logging.getLogger('TestFramework')
+        self.log.setLevel(logging.DEBUG)


I think DEBUG is good here. We shouldn't encourage people to log messages at custom levels (ie not one of debug, info, warning, error and critical), and we especially shouldn't encourage people to log at a level lower than DEBUG.

Actually setting DEBUG seems to be needed here in order to be able to see debug messages at all, otherwise python seems to fall back to root logger level which is WARNING.

Still I would consider dropping the "fh.setLevel()" call below. Having that call seems less like "not encouraging" people to log messages at custom levels, and more like going out of our way to punish and confuse them.

jnewbery · 2017-03-07T15:44:18Z

@ryanofsky's comments addressed and repushed: c9755da / https://github.com/jnewbery/bitcoin/tree/pr9768.3

jnewbery · 2017-03-07T20:19:32Z

rebased: 2c9fc0e / https://github.com/jnewbery/bitcoin/tree/pr9768.4

jnewbery · 2017-03-08T14:42:28Z

@laanwj @MarcoFalke I think this is a real improvement and helps debugging and fixing test cases when they fail. I've addressed #9768 (comment) in #9780 which builds off this PR. Any chance I can convince you to take a look at this?

ryanofsky

utACK f546d06ac21e2953c0dc0b1d8fef459b186781ce

Thanks for supporting -l0.

I think this is a real improvement and helps debugging and fixing test cases when they fail.

Definitely agree. It should be especially useful to easily see interleaved python and bitcoin debug.log output while debugging.

ryanofsky · 2017-03-08T16:49:03Z

qa/rpc-tests/proxy_test.py

Line 72 Warning: testing without local IPv6 support above is now a print again, not sure if this was intentional.

yes - proxy_test does a lot of work in the __init__() method, which is called before the temp directory is set up. Logging requires the temp directory, so we can't use self.log until we're in main() and _start_logging() has been called.

I left this as a print() rather than trying to do anything clever to coerce the test into being log friendly.

maflcko · 2017-03-08T22:31:07Z

Concept ACK. Going to give some feedback later tonight.

…

On Wed, Mar 8, 2017 at 3:42 PM, John Newbery ***@***.***> wrote: @laanwj @MarcoFalke I think this is a real improvement and helps debugging and fixing test cases when they fail. I've addressed #9768 (comment) in #9780 which builds off this PR. Any chance I can convince you to take a look at this? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or mute the thread.

maflcko

utACK f546d06

maflcko · 2017-03-09T00:35:35Z

qa/rpc-tests/invalidateblock.py

If you remove the prints above, you need to change those to assert_equal to maintain the debug print in case of failure.

maflcko · 2017-03-09T00:48:40Z

qa/rpc-tests/test_framework/mininode.py

Please don't change indentation here.

Oops. Fixed.

maflcko · 2017-03-09T00:54:02Z

qa/rpc-tests/test_framework/test_framework.py

Any reason you switched the rpc handler to stderr by falling back to the default value?

No reason. Just an oversight. Now fixed.

maflcko · 2017-03-09T01:05:41Z

qa/rpc-tests/test_framework/test_framework.py

You might need to shutdown (flush) the logs here.

maflcko · 2017-03-09T01:06:58Z

qa/rpc-tests/p2p-segwit.py

You don't need the assert(False) when you pass any AssertionError below. Though maybe a fix for an unrelated follow up pr.

That's pre-existing behaviour, which is unrelated to this PR. I agree it should be fixed in a different PR.

maflcko · 2017-03-09T01:16:18Z

qa/rpc-tests/test_framework/test_framework.py

I think the print to stdout can use a formatter that produces smaller lines. (Maybe without the timestamp?) But no strong opinion.

I specifically set the format of the logs to be the same as what bitcoind produces with microsecond logging.

Sjors · 2017-11-27T13:46:19Z

This works if you call test/functional/bumpfee.py --loglevel=INFO, but not if you call test/functional/test_runner.py --loglevel=INFO bumpfee (which just shows dots). Not sure if that's intended, but it did confuse me.

jnewbery · 2017-11-27T14:49:52Z

documentation is here: https://github.com/bitcoin/bitcoin/blob/master/test/README.md#test-logging :

when run through the test_runner harness, all logs are written to test_framework.log and no logs are output to the console.

Feel free to open a PR if you think the documentation could be improved.

Sjors · 2017-11-27T17:10:49Z

@JNewberry it's probably sufficient if /test_runner.py --help says that next to the --loglevel flag (or if it doesn't show that option).

jnewbery · 2017-11-27T17:33:36Z

The help text for --loglevel comes from test_framework.py. test_runner.py grabs that help text and appends it to its own help text. I suppose that test_runner could remove the --loglevel help before displaying it. The relevant code is here:

bitcoin/test/functional/test_runner.py

Line 258 in a892218

if args.help:

Sjors · 2017-11-27T18:34:39Z

Thanks, I'll take a look.

fanquake added the Tests label Feb 15, 2017

jnewbery mentioned this pull request Feb 16, 2017

Suppress noisy output from qa tests in Travis #9780

Merged

ryanofsky reviewed Feb 16, 2017

View reviewed changes

jnewbery force-pushed the rpctestlogging branch 2 times, most recently from 7f55a3e to 3b336ab Compare March 6, 2017 19:12

ryanofsky reviewed Mar 6, 2017

View reviewed changes

jnewbery force-pushed the rpctestlogging branch 2 times, most recently from a00ec22 to c9755da Compare March 7, 2017 15:28

jnewbery force-pushed the rpctestlogging branch 3 times, most recently from 3f35e24 to 2c9fc0e Compare March 7, 2017 20:18

jnewbery force-pushed the rpctestlogging branch from 2c9fc0e to f546d06 Compare March 7, 2017 23:46

jnewbery mentioned this pull request Mar 7, 2017

rpc-tests.py: Too many "Error: Unable to start HTTP server. See debug log for details." #9317

Closed

ryanofsky reviewed Mar 8, 2017

View reviewed changes

jnewbery changed the title ~~[qa] [WIP] Add logging to test_framework.py~~ [qa] Add logging to test_framework.py Mar 8, 2017

maflcko reviewed Mar 9, 2017

View reviewed changes

jnewbery force-pushed the rpctestlogging branch 2 times, most recently from b7dfc9e to f2751d5 Compare March 9, 2017 14:22

laanwj mentioned this pull request Mar 12, 2017

UNIX sockets support for RPC #9919

Closed

This was referenced May 6, 2017

[integration test] A litnode receiving Bitcoin from regtest network mit-dci/lit#54

Closed

Test framework improvements mit-dci/lit#61

Closed

UdjinM6 mentioned this pull request Oct 24, 2017

Third batch of per-utxo backports (up until 0.15, excluding actual per-utxo) dashpay/dash#1697

Merged

jnewbery deleted the rpctestlogging branch November 27, 2017 17:28

bitcoin locked as resolved and limited conversation to collaborators Dec 16, 2021

[qa] Add logging to test_framework.py #9768

[qa] Add logging to test_framework.py #9768

Uh oh!

Conversation

jnewbery commented Feb 15, 2017

Uh oh!

laanwj commented Feb 16, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jnewbery commented Feb 16, 2017

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ryanofsky commented Feb 17, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jnewbery commented Feb 17, 2017

Uh oh!

jnewbery commented Feb 22, 2017

Uh oh!

sdaftuar commented Feb 27, 2017

Uh oh!

jnewbery commented Feb 28, 2017

Uh oh!

jnewbery commented Mar 6, 2017

Uh oh!

ryanofsky left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

laanwj commented Feb 16, 2017 •

edited

Loading

ryanofsky commented Feb 17, 2017 •

edited

Loading

ryanofsky Mar 8, 2017 •

edited

Loading