Per-Peer Message Capture #19509

This PR introduces per-peer message capture into Bitcoin Core. 📓

Purpose

The purpose and scope of this feature is intentionally limited. It answers a question anyone new to Bitcoin’s P2P protocol has had: “Can I see what messages my node is sending and receiving?”.

Functionality

When a new debug-only command line argument capturemessages is set, any message that the node receives or sends is captured. The capture occurs in the MessageHandler thread. When receiving a message, it is captured as soon as the MessageHandler thread takes the message off of the vProcessMsg queue. When sending, the message is captured just before the message is pushed onto the vSendMsg queue.

The message capture is as minimal as possible to reduce the performance impact on the node. Messages are captured to a new message_capture folder in the datadir. Each node has their own subfolder named with their IP address and port. Inside, received and sent messages are captured into two binary files, msgs_recv.dat and msgs_sent.dat, like so:

0message_capture/203.0.113.7:56072/msgs_recv.dat
1message_capture/203.0.113.7:56072/msgs_sent.dat

Because the messages are raw binary dumps, included in this PR is a Python parsing tool to convert the binary files into human-readable JSON. This script has been placed on its own and out of the way in the new contrib/message-capture folder. Its usage is simple and easily discovered by the autogenerated -h option.

Future Maintenance

I sympathize greatly with anyone who says “the best code is no code”.

The future maintenance of this feature will be minimal. The logic to deserialize the payload of the p2p messages exists in our testing framework. As long as our testing framework works, so will this tool.

Additionally, I hope that the simplicity of this tool will mean that it gets used frequently, so that problems will be discovered and solved when they are small.

FAQ

“Why not just use Wireshark”

Yes, Wireshark has the ability to filter and decode Bitcoin messages. However, the purpose of the message capture added in this PR is to assist with debugging, primarily for new developers looking to improve their knowledge of the Bitcoin Protocol. This drives the design in a different direction than Wireshark, in two different ways. First, this tool must be convenient and simple to use. Using an external tool, like Wireshark, requires setup and interpretation of the results. To a new user who doesn’t necessarily know what to expect, this is unnecessary difficulty. This tool, on the other hand, “just works”. Turn on the command line flag, run your node, run the script, read the JSON. Second, because this tool is being used for debugging, we want it to be as close to the true behavior of the node as possible. A lot can happen in the SocketHandler thread that would be missed by Wireshark.

Additionally, if we are to use Wireshark, we are at the mercy of whoever it maintaining the protocol in Wireshark, both as to it being accurate and recent. As can be seen by the many previous attempts to include Bitcoin in Wireshark (google “bitcoin dissector”) this is easier said than done.

Lastly, I truly believe that this tool will be used significantly more by being included in the codebase. It’s just that much more discoverable.

Concept ACK the high-level idea. I think this feature may be quite useful while debugging, and it requires very few lines of code.

I have two questions though:

1. How to better integrate it with the existing codebase? Should the format be similar to what we have now: received: addr (30003 bytes) peer=0? Or maybe it doesn’t matter.
2. Is there any threat of this feature being used for DoS? Perhaps on a system where file create is expensive, an attacker could disconnect/reconnect (from a new net address?) to make us create a new file? Maybe the file should be created after 1 minute of connection lifetime? (Although the messages from the very beginning should not be lost).

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

Conflicts

Reviewers, this pull request conflicts with the following ones:

• #20404 (Remove names from translatable strings by hebasto)

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.

Concept ACK. I’m looking forward to playing around with this.

My first thought is that this would be much more useful if the user was able to specify an individual peer to log messages for, either through a command line argument -logmessages=<ip_addr> or through an RPC to enable and disable logging. Perhaps that can be done in a follow-up PR?

Concept ACK: Very nice feature! Looking forward to using it. Thanks for adding it.

Feature request: Would it be possible to add a flag to the Python script that writes the recorded messages to one file each in the binary format the ProcessMessage(…) fuzzers expect (src/test/fuzz/process_message.cpp and src/test/fuzz/process_messages.cpp)?

Ideally with a file naming convention matching that of what libFuzzer and many other fuzzers generate: the file name being the SHA-1 of the file content.

That way this feature could be used to record live network messages that could be used directly as fuzzing inputs. A great way to generate a fuzzing seed corpus. That would be super neat! :)

git range-diff master cf5966a 9898fa1

Made suggested changes and fixed the Travis problem.

@naumenkogs thanks for the concept ack!

How to better integrate it with the existing codebase? Should the format be similar to what we have now: received: addr (30003 bytes) peer=0? Or maybe it doesn’t matter.

IMO that format is good for a debug log, where things need to be compact on a single line. For this I much prefer JSON.

Is there any threat of this feature being used for DoS? …

At the moment, with this locked behind a debug flag, I’m not worried about DoS vectors. For both debugging and learning someone should be at the keyboard and the node shouldn’t be working with anything real. Additionally, I imagine that if writing a very small amount to disk in this way (every time a message is sent or received) is a DoS vector then there are many more serious ones available.

That said, this is worth consideration, especially if we think this will one day be used for wider purposes.

git range-diff master 9898fa1 cbb154e

• Trivial Rebase
• Added a commit at the beginning cleaning up PushMessage’s and ProcessMessages’s if statements
• LogMessage now uses Span
• command -> msg_type
• python import is now relative to file
• other small comments and fixes

git range-diff master cbb154e 863c6b5

• Added Test
• Fixed Travis warning
• Made Time Mockable

Huge Concept ACK! Very nice idea with simple implementation, I’m also pretty sure this will be very helpful for debugging purposes. Will definitely code-review that within the next days.

Just one detail I find quite odd: why create two files instead of just one and not rather include the direction as part of the serialization for each message? Is it only about saving disk space (1 byte per message) or is there another reason I’m not aware of? I’ve never seen a logging/sniffing tool that divides up into multiple files before and tend to think it would only complicate re-assembling the whole send/receive order later.

@theStack Thanks for the concept ACK!

why create two files instead of just one

Good question; I considered a few ways of doing this. Just to be clear, I create two files per peer. Partially, yes, this saves 1 byte per message. I could have also just logged everything into one file, which meant I would have had to save the peer address alongside each message as well. Ultimately, I chose the current way with the intention of simplifying the usage of the parser. As it stands, the parser is a simple “just give me what you want me to parse” sort of program. This allows the user to take advantage of globbing when selecting which files to parse (e.g. **/*.dat or **/msgs_recv.dat). Additionally the parser, being written in python, is actually noticeably slow. Forcing it to process all of the messages and then filter would be unnecessarily inconvenient.

why create two files instead of just one

Good question; I considered a few ways of doing this. Just to be clear, I create two files per peer. Partially, yes, this saves 1 byte per message. I could have also just logged everything into one file, which meant I would have had to save the peer address alongside each message as well. Ultimately, I chose the current way with the intention of simplifying the usage of the parser. As it stands, the parser is a simple “just give me what you want me to parse” sort of program. This allows the user to take advantage of globbing when selecting which files to parse (e.g. **/*.dat or **/msgs_recv.dat). Additionally the parser, being written in python, is actually noticeably slow. Forcing it to process all of the messages and then filter would be unnecessarily inconvenient.

Generally I’d say it makes sense to divide up into files/folders by criteria that I would likely use as frequent search key for accessing the logging data. Would I often want to access logs for a certain peer? Absolutely. Would I want to see only incoming or outcoming messages for a certain peer? Very unlikely, as the resulting data is probably not very valueable without the whole request/response stream in both directions. On the other hand, your arguments for simplification, efficiency (if only looking for incoming or outcoming messages is really such a frequent operation) and flexibility are also very strong, hence this solution is also okay with me.

I reviewed the code in more detail and noticed that there may be a serialization endianness problem, see the comments soon following below.

I don’t find your “why not Wireshark?” very convincing… If anything, it made me less sure this should get merged.

Wireshark is a fairly simple and standard tool. Glancing at the code, this PR is basically just a less-user-friendly reinvention thereof.

If there are concerns with maintenance of the Wireshark dissector, as I understand it, we could fork it and maintain it out of Wireshark’s codebase.

git range-diff master 863c6b5 f5fffb7

• Enforced little-endian writing to match parser
• Test uses assert_equal when possible

I’ve been playing around with this and it’s great. Just a few small comments so far.

The parser is printing hashes as large floats. Is it possible to print the hex representation:

 0  {
 1    "msgtype": "getheaders",
 2    "hashstop": 0,
 3    "locator": {
 4      "nVersion": 70015,
 5      "vHave": [
 6        6.450434035588393e+53,
 7        7.713140798064138e+53,
 8        2.6493031207713062e+53,
 9        1.0843487835635608e+54,
10        6.8089734462318345e+53,
11        1.4434627912104054e+54,
12        3.0470281418447093e+53,
13        4.1428701739036675e+53,
14        ...

git range-diff master 6095431 0547b23

• Values coming from uint256 variables print as hex correctly
• Restructured the output, renamed some fields
• Some whitespace fixes
• Small change to msg_generic (unused) in messages.py

git range-diff master 0547b23 4205c56

• peer logging -> message logging
• command -> msgtype
• Removed unneeded size_t cast
• Parser now properly handles unrecognized messages
• Parser now verified payload length

Regarding mini_parser in the functional test: discussion here. The popular question is “Why reimplement the parser here, as opposed to just calling contrib/message-logging/message-logging-parser.py?”

The main reason, which I agree with, is brought up by @jnewbery.

I think it’s much better not to assume that the contrib directory is available. Functional tests can be run when the build directory is out of tree and the source directory is not available. It makes sense to me to have a limited parser in the test case rather than importing from somewhere else.

Additionally, I think that this separate mini_parser makes it clear, at a glance, what exactly is being tested. As noted in the module docstring of p2p_message_logging.py, the message logging parser isn’t tested in this test. This test is for LogMessage only. I would hate to run into a Hubble Space Telescope-like problem where LogMessage is wrong but the message logging parser is wrong in the same way, so the errors go by unnoticed.

git range-diff master 4205c56 555e48a

• Rebased (trivial)
• Now uses MakeUCharSpan as suggested here
• Now accounts for the increase in file descriptor usage (by one)
  • This will be improved in #18911

I tested the logging parser on my system (running Python 3.5.2) and got the following error:

 0$ contrib/message-logging/message-logging-parser.py /tmp/bitcoin_func_test_9sw28m5f/node0/regtest/message_logging/127.0.0.1\:33370/*.dat
 1/tmp/bitcoin_func_test_9sw28m5f/node0/regtest/message_logging/127.0.0.1:33370/msgs_recv.dat
 2<class 'pathlib.PosixPath'>
 3Traceback (most recent call last):
 4  File "contrib/message-logging/message-logging-parser.py", line 129, in <module>
 5    main()
 6  File "contrib/message-logging/message-logging-parser.py", line 117, in main
 7    process_file(log, messages, "recv" in log.stem)
 8  File "contrib/message-logging/message-logging-parser.py", line 73, in process_file
 9    with open(path, 'rb') as f_in:
10TypeError: invalid file: PosixPath('/tmp/bitcoin_func_test_9sw28m5f/node0/regtest/message_logging/127.0.0.1:33370/msgs_recv.dat')

Turns out that open() is capable to take os.PathLike objects only from Python 3.6 onwards, see https://stackoverflow.com/a/42694113 Since we are still on Python 3.5 (though there is already a PR for changing to 3.6, see #19504), this should be fixed by converting the path to a string by opening str(path) instead.

git range-diff master 555e48a 4fc2e39 @theStack thanks for catching that! I had been running this all under the wrong environment the whole time. (I’ll plug conda here, never worry about your python environment again: just make sure to pick the right one)

In fixing this I ran into a current python bug! https://discuss.python.org/t/pathlib-absolute-vs-resolve/2573

TL;DR: if you want an absolute path to a file that may not exist, in Python 3.5, always use Path.cwd() / Path(arg). This is due to the “strictness” of resolve() discussed here.

@luke-jr says:

I don’t find your “why not Wireshark?” very convincing… If anything, it made me less sure this should get merged. Wireshark is a fairly simple and standard tool. Glancing at the code, this PR is basically just a less-user-friendly reinvention thereof. If there are concerns with maintenance of the Wireshark dissector, as I understand it, we could fork it and maintain it out of Wireshark’s codebase.

I’m inclined to agree. Also with a more general system like tracepoints we could do low overhead p2p(& other subsystem) tracing/filtering/scripting without any custom code

approach ACK. this is super cool! thank you for building it!

I’ve read over the commits, but don’t feel familiar enough with many of the components & relevant concerns (yet) to leave a proper review ACK. left a couple questions though.

I tried this out locally & it works great. I think it would be helpful to add some light documentation within the repo with the basics of how-to-use that you’ve mentioned on this PR. By basics I mean things like run node with -logmessages, the file structure of the message_logging dir & passing through contrib/message-logging/message-logging-parser.py to interpret.

The one trick I found very useful is using message_logging/[ip address]/*.dat as the arg for the message parser, since it interpolates the sent & received messages from the peer. I gleaned this from your comment earlier because I agree with @theStack about a common desired use case as accessing all logs for a certain peer. Your reasoning behind having sent vs received as separate files makes perfect sense, and I’m happy that the message parser supports the use case nicely. My request here is something simple to make this interface more apparent.

thanks again for this PR! I’m excited to query my node more and level up my jq skills.

It pains me a bit that this circumvents the existing logging infrastructure. Why is it not the case this is all just logged to debug.log (like everything else) and the parser works on that, filtering peer messages?

As @jnewbery points out below, I totally missed that this was binary logging! I should have looked more carefully.

It pains me a bit that this circumvents the existing logging infrastructure. Why is it not the case this is all just logged to debug.log (like everything else) and the parser works on that, filtering peer messages?

This PR dumps binary serialized messages (not text) to file, which is then post-processed by other software. The msgs_*.dat files can be enormous - hundreds of megabytes if blocks are being sent over that connection. Converting those messages to printable text and dropping them into the debug.log file would make them larger still, overwhelm the standard debug logging (eg a block message converted to hex would be millions of characters), and probably be a performance bottleneck (since all messages logged to debug.log would need to be deserialized and passed through tinyformat.h).

I think this also answers your other questions:

I don’t think “.dat” is the right extension. These are logs, not data, and should end in “.log”.

.log to me suggests printable text log files. These are binary files that need post-processing before they’re readable.

Regarding the “why not use Wireshark?” discussion:

I don’t know about which use cases others are thinking about, but having this in master would help me a lot at least:

I will use this feature in ways not suitable for Wireshark: both for long-term permanent capture of messages for after-the-fact trouble-shooting/debugging, and also for capturing messages that can be fed as seeds into the net message fuzzers.

I’ve played with this PR a bit and it covers my needs: I certainly hope it will land in master :)

I think this is a clear Concept ACK for new contributors.

I was unsure on the Concept ACK for longer term contributors. The fact that this is useful for some longer term contributors (e.g. @theStack, @practicalswift) convinces me it is just about a Concept ACK given the low cost (future maintenance, additional complexity).

If there are concerns with maintenance of the Wireshark dissector, as I understand it, we could fork it and maintain it out of Wireshark’s codebase.

This sounds like it would be more work and in the absence of someone saying they are keen to do this I think it is an overall Concept ACK for this PR from me.

(Excellent initial motivation section from @troygiorshev and fair challenge from @luke-jr)

Approach ACK.

Given the minimal new code it sounds like a win to relieve developers to install yet another debugging tool. Debugging tool which may not be accurate given the steady rate of new p2p messages (block filters, erlay, wtxid, …) or running cross-platform. If now one used it would be easy to remove it.

git range-diff master 4fc2e39 ff3a39c

Thanks for the review everyone!

Improvement

• Added a progress bar to the parser

Fixes

• Now uses GetBoolArg as opposed to IsArgSet
• IP addresses now have colons replaced with underscores
• One LogMessage call site is moved, as per this comment
• LogMessage now takes a CAddress& as opposed to a CNode&
• Clarified some comments

Next up, a rename and some light documentation!

Concept ACK

Will do testing and deeper review when CI is green. Mostly ignored the python code for now. Travis failed with running out of disc space but it would surprise me if that was related, so I restarted it. I don’t think I can restart Cirrus CI.

git range-diff master ff3a39c ba68f02

trivial rebase

git range-diff master ba68f02 5d5aeca

Rebased

git range-diff master 5d5aeca 18bcf97

• Renamed “Logging” to “Capture” throughout!

git range-diff master 18bcf97 d2d3d12

• Now uses seek instead of read
• Fixed mininode to p2p problem
• Removed unneeded optimistic_send boolean from PushMessage

Still TODO: Documentation!

Tested ACK d2d3d12d94477d0d377c82738832dfca2ac9e531

Looking forward to having this in master. This functionality is super useful for 1.) learning purposes, 2.) troubleshooting purposes, and 3.) fuzzing purposes (easy generation of seed corpora from actual message data).

I encourage others to review. To try this out:

0$ gh checkout pr 19509 && make distclean && ./autogen.sh && ./configure --with-incompatible-bdb && make
1$ src/bitcoind -capturemessages
2# now look in ~/.bitcoin/message_capture/

The availability of easy-to-use built-in tools such as this and bitcoin-cli -netinfo which allow for easy debugging/inspection of the P2P layer of Bitcoin Core will make the road to P2P understanding so much easier/quicker for future generations of Bitcoin Core contributions. Neat feature with great long-term benefits @troygiorshev! Thanks! :)

git range-diff master d2d3d12 d0ffb34

• Fixed remaining mininode to p2p issue
• Added documentation!

git range-diff master d0ffb34 9a9314a

• Rebased to master to fix Travis

All pending TODOs for this PR are complete. Thanks to everyone who has reviewed so far, should be an easy reACK from many of you!

Removed my ACK (temporarily) in light of @MarcoFalke’s comment about the unrelated change in src/net.cpp.

Hopefully that will be resolved soon and I’d be glad to re-review :)

git range-diff master 9a9314a 2418ec6

• Reverted the change to optimisticSend

Travis should™ pass now. I can’t get the fuzz tests to build, but I get the same linker error on master as I do here, so I assume it’s unrelated.

The changes themselves LGTM. However, while testing the feature on mainnet, the parsing tool contrib/message-capture/message-capture-parser.py encountered a problem decoding the following version message:

0$ xxd -g1 msgs_recv.dat
100000000: 75 da 89 ca 28 b4 05 00 76 65 72 73 69 6f 6e 00  u...(...version.
200000010: 00 00 00 00 6b 00 00 00 60 ea 00 00 00 00 00 00  ....k...`.......
300000020: 00 00 00 00 95 68 b1 5f 00 00 00 00 01 00 00 00  .....h._........
400000030: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ff ff  ................
500000040: d9 4f b2 14 20 8d 01 00 00 00 00 00 00 00 00 00  .O.. ...........
600000050: 00 00 00 00 00 00 00 00 ff ff 00 00 00 00 00 00  ................
700000060: 25 08 55 ca 19 a0 39 05 15 2f 62 69 74 63 6f 69  %.U...9../bitcoi
800000070: 6e 2d 73 65 65 64 65 72 3a 30 2e 30 31 2f 30 57  n-seeder:0.01/0W
900000080: 05 00 00                                         ...

This output can be converted back to the binary file via xxd -r hexdump.txt. If anyone has a better idea how to share binary data for reviewing here (probably base64 or alike?), I’d be glad to hear it.

 0$ contrib/message-capture/message-capture-parser.py ~/.bitcoin/message_capture/78.244.132.5_52410/*
 1Processing /home/honeybadger/.bitcoin/message_capture/78.244.132.5_52410/msgs_recv.dat
 2Traceback (most recent call last):
 3  File "contrib/message-capture/message-capture-parser.py", line 178, in <module>
 4    main()
 5  File "contrib/message-capture/message-capture-parser.py", line 160, in main
 6    process_file(str(capture), messages, "recv" in capture.stem, progress_bar)
 7  File "contrib/message-capture/message-capture-parser.py", line 117, in process_file
 8    assert_equal(length, payload_length)
 9  File "contrib/message-capture/../../test/functional/test_framework/util.py", line 50, in assert_equal                                                                                                   
10    raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
11AssertionError: not(107 == 106)

It seems like the deserialization routine for msg_version is consuming one byte less than expected. Guess that has to do with the optional fRelay field at the end. See also BIP37 and BIP60 – the latter is a draft, but it seems to summarize perfectly the problem we have here.

git range-diff master 2418ec6 4690881

• Fixed version fRelay bug
  • The parser now more closely matches how parsing works in the test framework and in bitcoind
• Documentation now follows PEP 0394
• Removed cat overuse in documentation

First of all, many thanks @theStack for both finding the bug and identifying exactly what causes it. Your guess was spot on and the links to the BIPs were very useful! It ended up identifying a small bug with how I implemented my message parser.

However, I’m not sure what to think about this message. Looking at it closely, it has the following:

• Version = 60000
• fRelay = 0 (1 byte)
• Declared payload size = 107
• Actual payload size = 107

The fRelay field is only supposed to exist as of version 70001. So this message is malformed. But, in the protocol’s implementation in bitcoind, we don’t check this.

This is a discrepancy between our testing framework and bitcoind. If fRelay was 1 for a message with version <70001, bitcoind would take it as a 1, whereas our testing framework would take it was a 0. I don’t think this will ever happen in the real world, but it’s worth noting. I’ve opened a PR to discuss this as #20411.

For now I take this as fixed.

Is there any chance this PR could get a release milestone?

FWIW I love this feature and would love to see it in master soon :) Thanks @troygiorshev!

So I am wondering if the message capture may ever write a message that can’t be parsed by our test code. And if there is a way to protect against this.

Ideally, in my mind, our test code should function as closely as possible to Core. So, if a message can be parsed by Core it should be able to be parsed by our test code. You’re right that this will get tricky for undefined behavior or broken messages like this.

For now I’ll add a MIN_PEER_PROTO_VERSION check as suggested in 14025.

Edit: We still have to have a way to deal with messages that fail to be deserialized by the test code. Doesn’t appear to be a problem, see below.

Oh, yeah you’re completely right, thanks.

Luckily (due to #19107) only messages with a valid header are pushed onto the vRecv queue, given to ProcessMessages, and parsed by the message capture parser. So we can trust that the header is workable. This will allow us to simply skip messages files that contain messages that fail deserilization, and we should be able to continue parsing all of the other ones.

I’ll think of a nice way to signal this to the user.

Edit: I think we’ll have to skip the entire file that contains a bad message, as a bad stated size will result in the next message being deserialized badly almost all of the time. I’ll experiment and see how best to fix this.

git range-diff master 4690881 abbb8ac

• Parser now no longer crashes when it reaches an unrecognized or broken message. Instead it simply skips that message and the rest of the file the message came from.
• Removed an unused import from the previous force push

git range-diff master abbb8ac d2e0f73

• Rebased

git range-diff master d2e0f73 af8bcd1

• Fixed two typos in documentation