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: contributor

    <!--e57a25ab6845829454e8d69fc972939a-->No more conflicts as of last run.

  6. DrahtBot cross-referenced this on Aug 22, 2018 from issue Preserve a format of RPC command definitions by kostyantyn
  7. DrahtBot cross-referenced this on Aug 22, 2018 from issue Refactoring CRPCCommand with enum category by isghe
  8. practicalswift commented at 8:06 AM on August 23, 2018: contributor

    Concept ACK

  9. 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?

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

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

  12. MarcoFalke force-pushed on Aug 23, 2018
  13. MarcoFalke commented at 3:29 PM on August 23, 2018: member

    Removed rpc

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

  15. 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:

        raise AssertionError(self._node_msg(msg))
    AssertionError: [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:
    
  16. 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:

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

            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.

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

  18. jnewbery commented at 3:56 PM on August 24, 2018: member

    ping @ryanofsky for review

  19. MarcoFalke force-pushed on Aug 24, 2018
  20. MarcoFalke force-pushed on Aug 24, 2018
  21. qa: Add TestNode::assert_debug_log fa3e9f7627
  22. MarcoFalke force-pushed on Aug 24, 2018
  23. 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.

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

  25. ryanofsky approved
  26. ryanofsky commented at 5:35 PM on August 24, 2018: contributor

    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.

  27. jnewbery commented at 5:53 PM on August 24, 2018: member

    utACK fa3e9f7627784ee00980590e5bf044a0e1249999

  28. MarcoFalke referenced this in commit 55c18a4530 on Aug 24, 2018
  29. MarcoFalke merged this on Aug 24, 2018
  30. MarcoFalke closed this on Aug 24, 2018

  31. MarcoFalke deleted the branch on Aug 24, 2018
  32. Bushstar cross-referenced this on Sep 4, 2018 from issue commits from bitcoin/master by Bushstar
  33. MarcoFalke referenced this in commit 07681b0735 on Sep 26, 2018
  34. MarcoFalke referenced this in commit 06544faff0 on Oct 25, 2018
  35. toxeus referenced this in commit 95d41806a1 on Nov 28, 2018
  36. PastaPastaPasta referenced this in commit 5ebd537d54 on Apr 16, 2020
  37. PastaPastaPasta referenced this in commit ff990120e9 on Apr 19, 2020
  38. PastaPastaPasta referenced this in commit 334f68c483 on Apr 20, 2020
  39. PastaPastaPasta referenced this in commit c75e7e2bad on Jun 12, 2020
  40. PastaPastaPasta referenced this in commit 6ab97cbfca on Jun 13, 2020
  41. PastaPastaPasta referenced this in commit b7d117c0ab on Jun 14, 2020
  42. bitcoin locked this on Sep 8, 2021

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: 2026-05-20 06:54 UTC