Net: Consistently log outgoing INV messages #15253

Empact commented at 4:05 AM on January 25, 2019: member

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 added the label P2P on Jan 25, 2019

Empact force-pushed on Jan 25, 2019

Empact commented at 5:49 AM on January 25, 2019: member

Possible concern: verbosity of the resultant logs

DrahtBot commented at 3:09 AM on January 26, 2019: 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:

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

in src/net.cpp:2608 in 67840b5701 outdated

2602 | @@ -2603,6 +2603,15 @@ int CConnman::GetBestHeight() const
2603 |      return nBestHeight.load(std::memory_order_acquire);
2604 |  }
2605 |  
2606 | +void CConnman::RelayInventory(const CInv& inv) const
2607 | +{
2608 | +    LogPrint(BCLog::NET, "Relaying inv %s\n", inv.ToString());

naumenkogs commented at 9:30 PM on January 28, 2019:

An inv may be further not sent due to a check inside PushInventory filterInventoryKnown.contains, so not sure how reasonable is this log :)

Empact commented at 8:47 AM on January 29, 2019:

Good point - this now only logs if the inv is actually to be relayed, and reports to how many peers it's being relayed.

Empact force-pushed on Jan 29, 2019

in src/net_processing.cpp:3645 in 50d97ff769 outdated

3491 | @@ -3497,9 +3492,11 @@ bool PeerLogicValidation::SendMessages(CNode* pto)
3492 |  
3493 |                      // If the peer's chain has this block, don't inv it back.
3494 |                      if (!PeerHasHeader(&state, pindex)) {
3495 | -                        pto->PushInventory(CInv(MSG_BLOCK, hashToAnnounce));
3496 | -                        LogPrint(BCLog::NET, "%s: sending inv peer=%d hash=%s\n", __func__,
3497 | -                            pto->GetId(), hashToAnnounce.ToString());
3498 | +                        CInv inv(MSG_BLOCK, hashToAnnounce);
3499 | +                        if (pto->PushInventory(inv)) {
3500 | +                            LogPrint(BCLog::NET, "%s: sending inv %s peer=%d\n",

naumenkogs commented at 1:01 AM on February 9, 2019:

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.

Empact commented at 9:33 PM on February 9, 2019:

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.

DrahtBot added the label Needs rebase on Feb 14, 2019

Empact force-pushed on Feb 26, 2019

Empact commented at 10:48 AM on February 26, 2019: member

Rebase for #14978 (81cd95884)

DrahtBot removed the label Needs rebase on Feb 26, 2019

naumenkogs commented at 6:41 PM on February 26, 2019: member

ACK

in src/net_processing.cpp:1297 in 918034b226 outdated

1203 | @@ -1204,15 +1204,6 @@ bool static AlreadyHave(const CInv& inv) EXCLUSIVE_LOCKS_REQUIRED(cs_main)
1204 |      return true;
1205 |  }
1206 |  
1207 | -static void RelayTransaction(const CTransaction& tx, CConnman* connman)
1208 | -{
1209 | -    CInv inv(MSG_TX, tx.GetHash());

MarcoFalke commented at 7:12 PM on February 26, 2019:

I'd prefer if that inv construction was kept in a function called RelayTransaction, where we pass in the tx(id). The caller should not be bothered dealing with inv-internals: E.g. that we can only push invs of type TX or BLOCK.

Empact commented at 7:18 AM on March 5, 2019:

Sounds good - I also split CNode::PushInventory into block and transaction variants for the same reason - all the callers were explicit and it simplified the callers.

DrahtBot added the label Needs rebase on Mar 4, 2019

Empact force-pushed on Mar 5, 2019

DrahtBot removed the label Needs rebase on Mar 5, 2019

DrahtBot added the label Needs rebase on Apr 1, 2019

Empact force-pushed on Apr 3, 2019

DrahtBot removed the label Needs rebase on Apr 3, 2019

DrahtBot added the label Needs rebase on May 4, 2019

MarcoFalke commented at 3:32 PM on May 8, 2019: member

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

[moveonly] net: Extract CConnman::RelayTransaction

Note the hashes passed more closely match the surrounding code.

80ace9ca62

Empact force-pushed on May 9, 2019

DrahtBot removed the label Needs rebase on May 9, 2019

net: Consistently log INV messages and their type

This requires splitting CNode::PushInventory into Block and Transaction
variants for the sake of the return information.

0bf2e504a1

Empact force-pushed on May 10, 2019

promag commented at 7:40 PM on May 16, 2019: member

@sdaftuar please give your feedback here too.

sdaftuar commented at 12:52 AM on May 17, 2019: member

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 commented at 5:11 PM on May 26, 2019: member

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 closed this on May 26, 2019

DrahtBot locked this on Dec 16, 2021