tests: add invalid P2P message tests #14522

jamesob commented at 5:46 PM on October 19, 2018: member

Adds p2p_invalid_messages.py: tests based on behavior for dealing with invalid and malformed P2P messages. Includes a test verifying that we can't DoS a node by spamming it with large invalid messages.
Adds TestNode.assert_memory_usage_stable: a context manager that allows us to ensure memory usage doesn't significantly increase on a node during some test.
Adds P2PConnection.send_raw_message: which allows us to construct and send messages with tweaked headers.

fanquake added the label Tests on Oct 19, 2018

DrahtBot commented at 9:49 AM on October 20, 2018: member

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

Conflicts

Reviewers, this pull request conflicts with the following ones:

#14519 (tests: add utility to easily profile node performance with perf by jamesob)

If you consider this pull request important, please also help to review the conflicting pull requests. Ideally, start with the one that should be merged first.

in test/functional/p2p_invalid_messages.py:76 in 435445ff01 outdated

  71 | +            self.log.info(
  72 | +                "Sending a bunch of large, junk messages to test "
  73 | +                "memory exhaustion. May take a bit...")
  74 | +
  75 | +            # Run a bunch of times to test for memory exhaustion.
  76 | +            for i in range(200):

practicalswift commented at 4:19 PM on October 22, 2018:

Use for _ in range(200): instead to show that the variable is intentionally unused :-)

in test/functional/test_framework/test_node.py:136 in 435445ff01 outdated

 125 | +            return None
 126 | +
 127 | +        try:
 128 | +            return int(subprocess.check_output(
 129 | +                "ps h -o rss {}".format(self.process.pid), shell=True).strip())
 130 | +        except Exception:

practicalswift commented at 4:20 PM on October 22, 2018:

Try to find a less general exception to catch :-)

conscott commented at 5:55 AM on October 23, 2018:

I think you are looking for subprocess.CalledProcessError :)

in test/functional/test_framework/test_node.py:304 in 435445ff01 outdated

 293 | +        yield
 294 | +
 295 | +        after_memory_usage = self.get_mem_rss()
 296 | +
 297 | +        if not (before_memory_usage and after_memory_usage):
 298 | +            self.log.warning("Unable to detect memory usage (RSS) - skipping memory check.")

conscott commented at 6:19 AM on October 23, 2018:

If this is expected to happen sometimes, (I would assume because ps isn't supported), might want to leave a comment as to why this check is being skipped rather than throwing an exception.

jamesob commented at 2:48 PM on October 23, 2018:

No exception thrown here - just a warning log statement and early return.

conscott commented at 3:01 PM on October 23, 2018:

Sorry - I didn't phrase that right. I meant, it may make sense to leave a comment as to why its okay to skip the check, and not just throw an exception (as some might expect to happen).

conscott commented at 3:16 PM on October 23, 2018:

Actually with the log from the CalledProcessError its fine, so please disregard :)

jamesob force-pushed on Oct 23, 2018

jamesob commented at 3:00 PM on October 23, 2018: member

Addressed @practicalswift nits.

conscott commented at 3:17 PM on October 23, 2018: contributor

ACK dfbb8624c3747f4e9e76c9b9a051e973857a15c3

jamesob force-pushed on Oct 24, 2018

jamesob commented at 8:02 PM on October 24, 2018: member

Pushed a small change to ensure get_mem_rss() failure is handled gracefully on Windows.

in test/functional/test_framework/test_node.py:306 in 56ecb6346e outdated

 301 | +        perc_increase_memory_usage = 1 - (float(before_memory_usage) / after_memory_usage)
 302 | +
 303 | +        if perc_increase_memory_usage > perc_increase_allowed:
 304 | +            self._raise_assertion_error(
 305 | +                "Memory usage increased over threshold of {}% from {} to {} ({}%)".format(
 306 | +                    perc_increase_allowed, before_memory_usage, after_memory_usage,

conscott commented at 5:51 AM on October 25, 2018:

Since you are displaying as a % instead of decimal, I think you just need to multiply by 100

.format(perc_increase_allowed*100, 
        before_memory_usage, 
        after_memory_usage, 
        perc_increase_memory_usage*100)

Now it'll show something like Memory usage increased over threshold of 3.0%....

in test/functional/test_framework/test_node.py:129 in 56ecb6346e outdated

 124 | +            self.log.warning("Couldn't get memory usage; process isn't running.")
 125 | +            return None
 126 | +
 127 | +        try:
 128 | +            return int(subprocess.check_output(
 129 | +                "ps h -o rss {}".format(self.process.pid), shell=True).strip())

laanwj commented at 6:01 PM on October 31, 2018:

I agree that dragging in python's pstools library is probably overkill for this however this needs testing on at least:

OpenBSD
FreeBSD
MacOSX

Also possiblity would be to skip it on 'unknown' platforms.

jamesob commented at 3:23 PM on November 1, 2018:

Instead of implementing something more sophisticated in this PR, I'm just going to skip it on platforms where ps doesn't work as this expects. If someone wants to drag in psutils in a later PR or implemented additional parsing logic, that sounds fine to me.

laanwj commented at 6:05 PM on October 31, 2018: member

looks good to me, thanks for adding testing for this particular corner

in test/functional/p2p_invalid_messages.py:1 in 56ecb6346e outdated

   0 | @@ -0,0 +1,175 @@
   1 | +#!/usr/bin/env python3

laanwj commented at 8:28 PM on October 31, 2018:

please add it to the test runner?

laanwj commented at 8:29 PM on October 31, 2018: member

checked: fails on FreeBSD:

user@vm13:~/bitcoin % test/functional/p2p_invalid_messages.py
2018-10-31T20:28:53.767000Z TestFramework (INFO): Initializing test directory /tmp/testw9nvke44
2018-10-31T20:28:54.336000Z TestFramework (ERROR): Unexpected exception caught during testing
Traceback (most recent call last):
  File "/usr/home/user/bitcoin/test/functional/test_framework/test_framework.py", line 172, in main
    self.run_test()
  File "test/functional/p2p_invalid_messages.py", line 69, in run_test
    with node.assert_memory_usage_stable(perc_increase_allowed=0.03):
  File "/usr/local/lib/python3.6/contextlib.py", line 81, in __enter__
    return next(self.gen)
  File "/usr/home/user/bitcoin/test/functional/test_framework/test_node.py", line 291, in assert_memory_usage_stable
    before_memory_usage = self.get_mem_rss()
  File "/usr/home/user/bitcoin/test/functional/test_framework/test_node.py", line 129, in get_mem_rss
    "ps h -o rss {}".format(self.process.pid), shell=True).strip())
ValueError: invalid literal for int() with base 10: b'RSS\n49084'
2018-10-31T20:28:54.405000Z TestFramework (INFO): Stopping nodes
2018-10-31T20:28:54.676000Z TestFramework (WARNING): Not cleaning up dir /tmp/testw9nvke44
2018-10-31T20:28:54.676000Z TestFramework (ERROR): Test failed. Test logging available at /tmp/testw9nvke44/test_framework.log
2018-10-31T20:28:54.677000Z TestFramework (ERROR): Hint: Call /usr/home/user/bitcoin/test/functional/combine_logs.py '/tmp/testw9nvke44' to consolidate all logs

jamesob force-pushed on Nov 1, 2018

jamesob commented at 3:24 PM on November 1, 2018: member

Addressed feedback from @laanwj and @conscott; thanks for the looks.

tests: add utility to assert node memory usage hasn't increased

Adds a utility to get resident set size memory usage for a test
node and a context manager that allows assertions based upon
maximum memory use increase.

5aa31f6ef2

tests: add P2PConnection.send_raw_message 62f94d39f8

tests: add tests for invalid P2P messages

E.g., ensure that we can't DoS a node by sending it a bunch of large,
unrecognized messages.

d20a9fa13d

jamesob force-pushed on Nov 1, 2018

conscott commented at 8:12 AM on November 6, 2018: contributor

Tested Re-ACK d20a9fa13d1c13f552e879798c0508be70190e71

laanwj commented at 10:15 AM on November 6, 2018: member

utACK d20a9fa13d1c13f552e879798c0508be70190e71

laanwj merged this on Nov 6, 2018

laanwj closed this on Nov 6, 2018

laanwj referenced this in commit 024816d6cf on Nov 6, 2018

jamesob deleted the branch on Nov 6, 2018

in test/functional/test_framework/test_node.py:307 in d20a9fa13d

 302 | +
 303 | +        if not (before_memory_usage and after_memory_usage):
 304 | +            self.log.warning("Unable to detect memory usage (RSS) - skipping memory check.")
 305 | +            return
 306 | +
 307 | +        perc_increase_memory_usage = 1 - (float(before_memory_usage) / after_memory_usage)

MarcoFalke commented at 10:49 PM on November 6, 2018:

You are taking after_memory_usage as reference, so a increase of n% in the memory usage will result always in perc_increase_memory_usage < n%.

For example you double the memory usage from 1GB to 2GB, this will give you 50%:

>>> 1 - (1 / 2)
0.5

Also you don't need the float conversion with /

in test/functional/test_framework/test_node.py:130 in d20a9fa13d

 125 | +            return None
 126 | +
 127 | +        try:
 128 | +            return int(subprocess.check_output(
 129 | +                "ps h -o rss {}".format(self.process.pid),
 130 | +                shell=True, stderr=subprocess.DEVNULL).strip())

MarcoFalke commented at 10:51 PM on November 6, 2018:

Why is shell required here?

in test/functional/test_framework/test_node.py:136 in d20a9fa13d

 131 | +
 132 | +        # Catching `Exception` broadly to avoid failing on platforms where ps
 133 | +        # isn't installed or doesn't work as expected, e.g. OpenBSD.
 134 | +        #
 135 | +        # We could later use something like `psutils` to work across platforms.
 136 | +        except Exception:

MarcoFalke commented at 10:52 PM on November 6, 2018:

I'd prefer to explicitly catch subprocess.SubprocessError and ValueError, so that KeyError et al is not caught.

in test/functional/test_framework/test_node.py:125 in d20a9fa13d

 120 | +
 121 | +        If process is stopped or `ps` is unavailable, return None.
 122 | +        """
 123 | +        if not (self.running and self.process):
 124 | +            self.log.warning("Couldn't get memory usage; process isn't running.")
 125 | +            return None

MarcoFalke commented at 10:53 PM on November 6, 2018:

Couldn't this be an assert? How is this different from calling an RPC method when the node is not running?

in test/functional/p2p_invalid_messages.py:119 in d20a9fa13d

 114 | +        # TODO: handle larger-than cases. I haven't been able to pin down what behavior to expect.
 115 | +        for wrong_size in (2, 77, 78, 79):
 116 | +            self.log.info("Sending a message with incorrect size of {}".format(wrong_size))
 117 | +
 118 | +            # Unmodified message should submit okay.
 119 | +            node.p2p.send_and_ping(msg)

MarcoFalke commented at 11:01 PM on November 6, 2018:

nit: Could assert debug log for unknown message type?

in test/functional/p2p_invalid_messages.py:144 in d20a9fa13d

 139 | +        #
 140 | +        # 3.
 141 | +        #
 142 | +        # Send a message with a too-long command name.
 143 | +        #
 144 | +        node.p2p.send_message(msg_nametoolong("foobar"))

MarcoFalke commented at 11:02 PM on November 6, 2018:

Could assert debug log with the exact error?

in test/functional/p2p_invalid_messages.py:135 in d20a9fa13d

 130 | +            try:
 131 | +                node.p2p.send_message(messages.msg_ping(nonce=123123))
 132 | +            except IOError:
 133 | +                pass
 134 | +
 135 | +            node.p2p.wait_for_disconnect(timeout=10)

MarcoFalke commented at 11:02 PM on November 6, 2018:

Could assert debug log?

MarcoFalke commented at 11:03 PM on November 6, 2018: member

Concept ACK. Nice tests!

MarcoFalke commented at 8:49 PM on November 7, 2018: member

Also, the test fails on macOS (with OSError: [Errno 41] Protocol wrong type for socket printed to stderr):

stdout:
2018-11-07T18:35:07.995000Z TestFramework (INFO): Initializing test directory /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/test_runner_₿_🏃_20181107_182921/p2p_invalid_messages_46
2018-11-07T18:35:08.836000Z TestFramework.node0 (ERROR): Unable to get memory usage
Traceback (most recent call last):
  File "/Users/travis/build/MarcoFalke/btc_nightly/bitcoin/test/functional/test_framework/test_node.py", line 130, in get_mem_rss
    shell=True, stderr=subprocess.DEVNULL).strip())
ValueError: invalid literal for int() with base 10: b'RSS\n 71200'
2018-11-07T18:35:08.838000Z TestFramework (INFO): Sending a bunch of large, junk messages to test memory exhaustion. May take a bit...
2018-11-07T18:35:20.251000Z TestFramework (INFO): Waiting for node to drop junk messages.
2018-11-07T18:35:20.330000Z TestFramework.node0 (ERROR): Unable to get memory usage
Traceback (most recent call last):
  File "/Users/travis/build/MarcoFalke/btc_nightly/bitcoin/test/functional/test_framework/test_node.py", line 130, in get_mem_rss
    shell=True, stderr=subprocess.DEVNULL).strip())
ValueError: invalid literal for int() with base 10: b'RSS\n 80896'
2018-11-07T18:35:20.331000Z TestFramework.node0 (WARNING): Unable to detect memory usage (RSS) - skipping memory check.
2018-11-07T18:35:20.393000Z TestFramework.mininode (WARNING): Connection lost to 127.0.0.1:11368 due to [Errno 41] Protocol wrong type for socket
2018-11-07T18:35:20.495000Z TestFramework (INFO): Sending a message with incorrect size of 2
2018-11-07T18:35:20.659000Z TestFramework (INFO): Sending a message with incorrect size of 77
2018-11-07T18:35:20.836000Z TestFramework (INFO): Sending a message with incorrect size of 78
2018-11-07T18:35:21.010000Z TestFramework (INFO): Sending a message with incorrect size of 79
2018-11-07T18:35:21.442000Z TestFramework (INFO): Stopping nodes
2018-11-07T18:35:21.803000Z TestFramework (INFO): Cleaning up /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/test_runner_₿_🏃_20181107_182921/p2p_invalid_messages_46 on exit
2018-11-07T18:35:21.803000Z TestFramework (INFO): Tests successful
stderr:
Fatal write error on socket transport
protocol: <test_framework.mininode.P2PDataStore object at 0x103d87e48>
transport: <_SelectorSocketTransport fd=10 read=polling write=<idle, bufsize=0>>
Traceback (most recent call last):
  File "/usr/local/Cellar/python/3.6.5_1/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py", line 761, in write
    n = self._sock.send(data)
OSError: [Errno 41] Protocol wrong type for socket

laanwj referenced this in commit af3c8a7e9f on Nov 12, 2018

jnewbery commented at 3:32 PM on February 21, 2019: member

I'm very late to this party, but my opinion is that testing memory usage is very useful, but should not be part of a functional test suite. Functional tests should test the functionality of the product, ie the outputs that are triggered by passing in various inputs. Memory usage is related to the implementation of the product. As the follow-on problems with this PR show, making rigid tests that depend on implementation details are brittle when run over different platforms.

I think that this code could be very useful when incorporated into a soak testing framework, but that it shouldn't be included in our functional test suite.

jamesob commented at 3:53 PM on February 21, 2019: member

I think that this code could be very useful when incorporated into a soak testing framework, but that it shouldn't be included in our functional test suite.

Probably worth adding some guidance around what is and isn't appropriate for the functional test suite in one of the READMEs.

I'm generally inclined to agree with you, but I think having a comprehensive and easy-to-use framework for adding checks like this is very worthwhile. I'm also inclined to think that packaging such a framework within this repo is probably worthwhile, though there are certainly arguments against that. What do you think about introducing some kind of decorator to denote these sorts of checks on individual test methods and then introducing an --extended-like flag for use with the runner?

jnewbery commented at 4:06 PM on February 21, 2019: member

Probably worth adding some guidance around what is and isn't appropriate for the functional test suite in one of the READMEs.

Good idea. I'll add that to my list (or I'm happy to review yours if you want to add it)

I think having a comprehensive and easy-to-use framework for adding checks like this is very worthwhile.

Also agree. The TestNode class is supposed to be reusable, eg for stress or soak testing.

I'm also inclined to think that packaging such a framework within this repo is probably worthwhile, though there are certainly arguments against that. What do you think about introducing some kind of decorator to denote these sorts of checks on individual test methods and then introducing an --extended-like flag for use with the runner?

I think including it in the repo is fine, but my preference would be to separate it somehow from the functional tests, for example having a soak testing framework that imports the TestNode() and then adds the methods it needs. I have a concern that /test/functional will continue to expand to be a test-all-the-things tool, even where other testing techniques are more appropriate.

deadalnix referenced this in commit c6a0647ada on May 21, 2020

ftrader referenced this in commit 969027e3c0 on Aug 17, 2020

random-zebra referenced this in commit bffe509aed on Jun 28, 2021

kittywhiskers referenced this in commit b7bee7cb6a on Aug 5, 2021

kittywhiskers referenced this in commit 11bd300809 on Aug 5, 2021

knst referenced this in commit bd754876f1 on Aug 10, 2021

kittywhiskers referenced this in commit 539bfcbd77 on Aug 12, 2021

knst referenced this in commit 548c9e9797 on Aug 16, 2021

kittywhiskers referenced this in commit e6cce7be6c on Aug 22, 2021

PastaPastaPasta referenced this in commit cf627fba6d on Aug 23, 2021

UdjinM6 referenced this in commit f38aa44bfd on Aug 29, 2021

DrahtBot locked this on Dec 16, 2021