qa: Add TestNode::assert_debug_log #14024

pull MarcoFalke wants to merge 1 commits into bitcoin:master from MarcoFalke:Mf1808-rpcDebugLog changing 2 files +25 −2
  1. MarcoFalke commented at 1:06 pm on August 22, 2018: member
    Closes #13006
  2. MarcoFalke force-pushed on Aug 22, 2018
  3. fanquake added the label Tests on Aug 22, 2018
  4. MarcoFalke force-pushed on Aug 22, 2018
  5. DrahtBot commented at 2:56 pm on August 22, 2018: member
  6. practicalswift commented at 8:06 am on August 23, 2018: contributor
    Concept ACK
  7. jnewbery commented at 2:04 pm on August 23, 2018: member
    Concept ACK asserting on the contents of the debug log, but I don’t understand why a new RPC method is needed. Why not read the debug log file directly?
  8. MarcoFalke commented at 2:09 pm on August 23, 2018: member
    @jnewbery I don’t think it is possible to read from a file that is opened for writing on windows with python.
  9. jnewbery commented at 2:11 pm on August 23, 2018: member

    I don’t think it is possible to read from a file that is opened for writing on windows with python.

    I’m NACKish on this. I don’t think we should be adding code to the product to work around a limitation in the test framework on a specific platform.

  10. MarcoFalke force-pushed on Aug 23, 2018
  11. MarcoFalke commented at 3:29 pm on August 23, 2018: member
    Removed rpc
  12. ken2812221 commented at 3:51 am on August 24, 2018: contributor
    Concept ACK. Seems like you’ve solve the problem on Windows, I’m able to pass p2p_invalid_tx test on Windows
  13. in test/functional/p2p_invalid_tx.py:146 in fa5a71a149 outdated 
    143+        self.restart_node(0, ['-enablebip61=0', '-persistmempool=0'])
144         self.reconnect_p2p(num_connections=1)
145-        node.p2p.send_txs_and_test([tx1], node, success=False, expect_disconnect=True)
146+        with node.assert_debug_log(expected_msgs=[
147+                re.escape("{} from peer=0 was not accepted: mandatory-script-verify-flag-failed (Invalid OP_IF construction) (code 16)".format(tx1.hash)),
148+                re.escape("disconnecting peer=0"),
    jnewbery commented at 3:17 pm on August 24, 2018:

    Passing in an escaped string means that the printed assert when this fails looks a bit weird, but no big deal:

    0    raise AssertionError(self._node_msg(msg))
1AssertionError: [node 0] Expected message "8d7190866370e089916899a483a8df5ce7b495b04ffefc841ecd0d5779e9a0ca\ asdf\ from\ peer\=0\ was\ not\ accepted\:\ mandatory\-script\-verify\-flag\-failed\ \(Invalid\ OP_IF\ construction\)\ \(code\ 16\)" does not partially match log:
  14. in test/functional/test_framework/test_node.py:247 in fa5a71a149 outdated 
    242+            with open(debug_log, encoding='utf-8') as dl:
243+                dl.seek(prev_size)
244+                log = dl.read()
245+            for expected_msg in expected_msgs:
246+                if re.search(expected_msg, log, flags=re.MULTILINE) is None:
247+                    self._raise_assertion_error('Expected message "{}" does not partially match log:\n"{}"\n'.format(expected_msg, log))
    jnewbery commented at 3:21 pm on August 24, 2018:

    Printing the log excerpt out in the assert is a bit confusing for anything that’s parsing the test_framework log (since the timestamps at the start of the line will be interpreted as new log lines. Can I convince you to make the following change:

    0@@ -242,9 +242,10 @@ class TestNode():
1             with open(debug_log, encoding='utf-8') as dl:
2                 dl.seek(prev_size)
3                 log = dl.read()
4+                print_log = " - " + "\n - ".join(log.splitlines())
5             for expected_msg in expected_msgs:
6                 if re.search(expected_msg, log, flags=re.MULTILINE) is None:
7-                    self._raise_assertion_error('Expected message "{}" does not partially match log:\n"{}"\n'.format(expected_msg, log))
8+                    self._raise_assertion_error('Expected message "{}" does not partially match log:\n\n{}\n\n'.format(expected_msg, print_log))

    so that the printed log lines are prefixed with -.

    I’d also be tempted to add a hint like:

    0        self.log.error("Expected Log not raised. Check that bitcoind log format output has not changed!")

    Changes to logging that cause tests to fail can be really annoying, so adding a hint is a friendly thing to do here.

  15. jnewbery commented at 3:22 pm on August 24, 2018: member

    This is great. Tested ACK fa5a71a1498f6934e3d30499c1e17e01903f5659 (tested by asserting for a missing log).

    I have a few nits inline.

  16. jnewbery commented at 3:56 pm on August 24, 2018: member
    ping @ryanofsky for review
  17. MarcoFalke force-pushed on Aug 24, 2018
  18. MarcoFalke force-pushed on Aug 24, 2018
  19. qa: Add TestNode::assert_debug_log fa3e9f7627
  20. MarcoFalke force-pushed on Aug 24, 2018
  21. in test/functional/test_framework/test_node.py:245 in fa3e9f7627 
    240+            yield
241+        finally:
242+            with open(debug_log, encoding='utf-8') as dl:
243+                dl.seek(prev_size)
244+                log = dl.read()
245+            print_log = " - " + "\n - ".join(log.splitlines())
    ryanofsky commented at 5:07 pm on August 24, 2018:
    Might be more efficient to move this line before the _raise_assertion_error call in case the variable is unused.
    MarcoFalke commented at 5:41 pm on August 24, 2018:
    I think we don’t optimize for performance in the test framework, so this should be fine.
  22. in test/functional/test_framework/test_node.py:234 in fa3e9f7627 
    229@@ -229,6 +230,23 @@ def is_node_stopped(self):
230     def wait_until_stopped(self, timeout=BITCOIND_PROC_WAIT_TIMEOUT):
231         wait_until(self.is_node_stopped, timeout=timeout)
232 
233+    @contextlib.contextmanager
234+    def assert_debug_log(self, expected_msgs):
    ryanofsky commented at 5:21 pm on August 24, 2018:
    I was surprised to see that this code actually works without adding RPCs before and after the yield to flush the log. But apparently there is a setbuf call in the logging code which disables buffering. Might be worth noting in a comment.
  23. ryanofsky approved
  24. ryanofsky commented at 5:35 pm on August 24, 2018: member

    utACK fad48e85d7a3f52d7df433e895689b19d117d157

    Though I actually do think the previous code adding the tail log RPC (https://github.com/bitcoin/bitcoin/commits/fa0b5ca98e096e64a4bc94e69d1dd09e682f29fc) was nice because the tail command seems handy, and it would let us turn on log buffering in the future.

  25. jnewbery commented at 5:53 pm on August 24, 2018: member
    utACK fa3e9f7627784ee00980590e5bf044a0e1249999
  26. MarcoFalke referenced this in commit 55c18a4530 on Aug 24, 2018
  27. MarcoFalke merged this on Aug 24, 2018
  28. MarcoFalke closed this on Aug 24, 2018
  29. MarcoFalke deleted the branch on Aug 24, 2018
  30. MarcoFalke referenced this in commit 07681b0735 on Sep 26, 2018
  31. MarcoFalke referenced this in commit 06544faff0 on Oct 25, 2018
  32. toxeus referenced this in commit 95d41806a1 on Nov 28, 2018
  33. PastaPastaPasta referenced this in commit 5ebd537d54 on Apr 16, 2020
  34. PastaPastaPasta referenced this in commit ff990120e9 on Apr 19, 2020
  35. PastaPastaPasta referenced this in commit 334f68c483 on Apr 20, 2020
  36. PastaPastaPasta referenced this in commit c75e7e2bad on Jun 12, 2020
  37. PastaPastaPasta referenced this in commit 6ab97cbfca on Jun 13, 2020
  38. PastaPastaPasta referenced this in commit b7d117c0ab on Jun 14, 2020
  39. MarcoFalke locked this on Sep 8, 2021


MarcoFalke DrahtBot practicalswift jnewbery ken2812221 ryanofsky

Labels
Tests

github-metadata-mirror

This is a metadata mirror of the GitHub repository bitcoin/bitcoin. This site is not affiliated with GitHub. Content is generated from a GitHub metadata backup.
generated: 2025-09-26 15:13 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me