Skip to content

Net: Consistently log outgoing INV messages #15253

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Closed
Empact wants to merge 2 commits into from
Closed

Net: Consistently log outgoing INV messages #15253

Empact wants to merge 2 commits into from

Conversation

@Empact
Copy link
Contributor

@Empact Empact commented Jan 25, 2019

These are logged in some cases, but not in others, which can make debugging test failures impractical in cases where the TX INVs are important.

Also fix the sending inv peer=%d hash=%s to explicitly note that a block inv was being sent.

Here's an example of where this might come in useful.

2019-01-25T01:39:16.043000Z TestFramework (INFO): Initializing test directory /tmp/test_runner_₿_🏃_20190125_013849/p2p_sendheaders_98
2019-01-25T01:39:17.467000Z TestFramework (INFO): Verify getheaders with null locator and valid hashstop returns headers.
2019-01-25T01:39:17.518000Z TestFramework (INFO): Verify getheaders with null locator and invalid hashstop does not return headers.
2019-01-25T01:39:17.622000Z TestFramework (INFO): Part 1: headers don't start before sendheaders message...
2019-01-25T01:39:18.061000Z TestFramework (INFO): Part 1: success!
2019-01-25T01:39:18.061000Z TestFramework (INFO): Part 2: announce blocks with headers after sendheaders message...
2019-01-25T01:39:25.881000Z TestFramework (INFO): Part 2: success!
2019-01-25T01:39:25.882000Z TestFramework (INFO): Part 3: headers announcements can stop after large reorg, and resume after headers/inv from peer...
2019-01-25T01:39:28.607000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/test_framework/test_framework.py", line 173, in main
    self.run_test()
  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/p2p_sendheaders.py", line 252, in run_test
    self.test_nonnull_locators(test_node, inv_node)
  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/p2p_sendheaders.py", line 392, in test_nonnull_locators
    inv_node.check_last_inv_announcement(inv=[tip])
  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/p2p_sendheaders.py", line 202, in check_last_inv_announcement
    assert_equal(compare_inv, inv)
  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/test_framework/util.py", line 39, in assert_equal
    raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
AssertionError: not([40204527931277807332276281381170204987709290312442988532095433649182475622986] == [30543910617856476296290423477244797212992354123001017184131728944424831123554])

From log previously held here: https://travis-ci.org/bitcoin/bitcoin/jobs/484159397 but since overwritten. I have the full log available locally if anyone is curious to see it.

@fanquake fanquake added the P2P label Jan 25, 2019
@Empact
Copy link
Contributor Author

Empact commented Jan 25, 2019

Possible concern: verbosity of the resultant logs

@DrahtBot
Copy link
Contributor

DrahtBot commented Jan 26, 2019 •
edited
Loading

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

Conflicts

Reviewers, this pull request conflicts with the following ones:

  • #15759 ([p2p] Add 2 outbound blocks-only connections by sdaftuar)

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.

naumenkogs
naumenkogs reviewed Jan 28, 2019
View reviewed changes
@Empact Empact force-pushed the inv-log branch 3 times, most recently from 7a7ca3d to 50d97ff Compare January 29, 2019 08:45
@Empact Empact mentioned this pull request Feb 1, 2019
Merged
naumenkogs
naumenkogs reviewed Feb 9, 2019
View reviewed changes
src/net_processing.cpp Outdated
Copy link
Contributor

@naumenkogs naumenkogs Feb 9, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It seems we can move this logging inside PushInventory for cases where inv is for block?
Then this code won't be duplicate in 2 places.

I'm also wondering whether we should put all logging (including transactions) there to have a uniform behavior, not sure though.

Copy link
Contributor Author

@Empact Empact Feb 9, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The main reason I didn't do that was to avoid multiple log entries when relaying to all peers, as in RelayInventory. A single message in that case is a lot less noisy.

@Empact
Copy link
Contributor Author

Empact commented Feb 26, 2019

Rebase for #14978 (81cd958)

@naumenkogs
Copy link
Contributor

naumenkogs commented Feb 26, 2019

ACK

maflcko
maflcko reviewed Feb 26, 2019
View reviewed changes
@Empact Empact force-pushed the inv-log branch 3 times, most recently from 9a2928a to 24e230f Compare March 5, 2019 07:20
@maflcko
Copy link
Member

maflcko commented May 8, 2019

@Empact Mind to split up the first two commits into a separate pull?

@Bushstar Bushstar mentioned this pull request May 8, 2019
Closed
@Empact
[moveonly] net: Extract CConnman::RelayTransaction
80ace9c 
Note the hashes passed more closely match the surrounding code.
@Empact Empact mentioned this pull request May 9, 2019
Closed
@Empact
net: Consistently log INV messages and their type
0bf2e50 
This requires splitting CNode::PushInventory into Block and Transaction
variants for the sake of the return information.
@promag
Copy link
Contributor

promag commented May 16, 2019

@sdaftuar please give your feedback here too.

@sdaftuar
Copy link
Member

sdaftuar commented May 17, 2019

I have no opinion about whether we should log all the txid's in an INV or not with -debug=net is enabled.

This implementation seems broken however -- in addition to the refactor being needlessly disruptive, it's incorrect logically to log a message about an inv being sent when PushInventory is called. It's not until we try to actually get to SendMessages for that peer and hit the poisson timeout before we determine whether to actually send a given txid to a peer, based on their filterInventoryKnown which may have changed from when we called PushInventory.

Because there's just one place in the code we send INV messages it should be straightforward to just print them out (either in CConnMan::PushMessage, where there is already a log message, or in net_processing's SendMessages() where we construct the INV).

@Empact
Copy link
Contributor Author

Empact commented May 26, 2019

Thanks, these are logged in PushMesaage, as you mention @sdaftuar. Just not in the CI logs. Seems some other work needs to be done, eg around publishing the full CI log artifacts or the like.

@Empact Empact closed this May 26, 2019
@bitcoin bitcoin locked as resolved and limited conversation to collaborators Dec 16, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.

Reviewers

2 more reviewers

@maflcko maflcko maflcko left review comments

@naumenkogs naumenkogs naumenkogs left review comments

Reviewers whose approvals may not affect merge requirements

Assignees

No one assigned

Labels

P2P

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

7 participants

@Empact @DrahtBot @naumenkogs @maflcko @promag @sdaftuar @fanquake