Skip to content

Commit e3f4b67

Browse files
mtrippledmtrippled
committed
Log outbound peer connection preparation.
Log lifecycle of peer connections in a single entry at beginning, and then when it ends. Log outbound connection attempts. Log peer connection when logging autoconnect preparation. Count total peers when checking autoconnect. Log untrusted validator lists.
1 parent 2216e5a commit e3f4b67

File tree

11 files changed

+191
-49
lines changed

11 files changed

+191
-49
lines changed

‎src/xrpld/app/misc/Manifest.h‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -353,7 +353,7 @@ class ManifestCache
353353
May be called concurrently
354354
*/
355355
ManifestDisposition
356-
applyManifest(Manifest m);
356+
applyManifest(Manifest m, std::unique_ptr<std::stringstream> const& ss = {});
357357

358358
/** Populate manifest cache with manifests in database and config.
359359

‎src/xrpld/app/misc/ValidatorList.h‎

Lines changed: 8 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -424,7 +424,8 @@ class ValidatorList
424424
uint256 const& hash,
425425
Overlay& overlay,
426426
HashRouter& hashRouter,
427-
NetworkOPs& networkOPs);
427+
NetworkOPs& networkOPs,
428+
std::unique_ptr<std::stringstream> const& ss = {});
428429

429430
/** Apply multiple published lists of public keys.
430431
@@ -452,7 +453,8 @@ class ValidatorList
452453
std::uint32_t version,
453454
std::vector<ValidatorBlobInfo> const& blobs,
454455
std::string siteUri,
455-
std::optional<uint256> const& hash = {});
456+
std::optional<uint256> const& hash = {},
457+
std::unique_ptr<std::stringstream> const& ss = {});
456458

457459
/* Attempt to read previously stored list files. Expected to only be
458460
called when loading from URL fails.
@@ -786,7 +788,8 @@ class ValidatorList
786788
std::uint32_t version,
787789
std::string siteUri,
788790
std::optional<uint256> const& hash,
789-
lock_guard const&);
791+
lock_guard const&,
792+
std::unique_ptr<std::stringstream> const& ss = {});
790793

791794
// This function updates the keyListings_ counts for all the trusted
792795
// master keys
@@ -879,7 +882,8 @@ class ValidatorList
879882
Json::Value& list,
880883
std::string const& manifest,
881884
std::string const& blob,
882-
std::string const& signature);
885+
std::string const& signature,
886+
std::unique_ptr<std::stringstream> const& ss = {});
883887

884888
/** Stop trusting publisher's list of keys.
885889

‎src/xrpld/app/misc/detail/Manifest.cpp‎

Lines changed: 12 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -379,7 +379,7 @@ ManifestCache::revoked(PublicKey const& pk) const
379379
}
380380

381381
ManifestDisposition
382-
ManifestCache::applyManifest(Manifest m)
382+
ManifestCache::applyManifest(Manifest m, std::unique_ptr<std::stringstream> const& ss)
383383
{
384384
// Check the manifest against the conditions that do not require a
385385
// `unique_lock` (write lock) on the `mutex_`. Since the signature can be
@@ -388,7 +388,7 @@ ManifestCache::applyManifest(Manifest m)
388388
// comment below), `checkSignature` only needs to be set to true on the
389389
// first run.
390390
auto prewriteCheck =
391-
[this, &m](auto const& iter, bool checkSignature, auto const& lock)
391+
[this, &m, &ss](auto const& iter, bool checkSignature, auto const& lock)
392392
-> std::optional<ManifestDisposition> {
393393
XRPL_ASSERT(
394394
lock.owns_lock(),
@@ -415,6 +415,10 @@ ManifestCache::applyManifest(Manifest m)
415415
{
416416
if (auto stream = j_.warn())
417417
logMftAct(stream, "Invalid", m.masterKey, m.sequence);
418+
if (ss) {
419+
*ss << to_string(m)
420+
<< ": not verified. Hence, the manifest is invalid";
421+
}
418422
return ManifestDisposition::invalid;
419423
}
420424

@@ -450,6 +454,12 @@ ManifestCache::applyManifest(Manifest m)
450454
<< ": is not revoked and the manifest has no "
451455
"signing key. Hence, the manifest is "
452456
"invalid";
457+
if (ss) {
458+
*ss << to_string(m)
459+
<< ": is not revoked and the manifest has no "
460+
"signing key. Hence, the manifest is "
461+
"invalid";
462+
}
453463
return ManifestDisposition::invalid;
454464
}
455465

‎src/xrpld/app/misc/detail/ValidatorList.cpp‎

Lines changed: 38 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -36,6 +36,7 @@
3636
#include <cmath>
3737
#include <numeric>
3838
#include <shared_mutex>
39+
#include <sstream>
3940

4041
namespace ripple {
4142

@@ -943,10 +944,11 @@ ValidatorList::applyListsAndBroadcast(
943944
uint256 const& hash,
944945
Overlay& overlay,
945946
HashRouter& hashRouter,
946-
NetworkOPs& networkOPs)
947+
NetworkOPs& networkOPs,
948+
std::unique_ptr<std::stringstream> const& ss)
947949
{
948950
auto const result =
949-
applyLists(manifest, version, blobs, std::move(siteUri), hash);
951+
applyLists(manifest, version, blobs, std::move(siteUri), hash, ss);
950952
auto const disposition = result.bestDisposition();
951953

952954
if (disposition == ListDisposition::accepted)
@@ -998,7 +1000,8 @@ ValidatorList::applyLists(
9981000
std::uint32_t version,
9991001
std::vector<ValidatorBlobInfo> const& blobs,
10001002
std::string siteUri,
1001-
std::optional<uint256> const& hash /* = {} */)
1003+
std::optional<uint256> const& hash /* = {} */,
1004+
std::unique_ptr<std::stringstream> const& ss)
10021005
{
10031006
if (std::count(
10041007
std::begin(supportedListVersions),
@@ -1019,7 +1022,8 @@ ValidatorList::applyLists(
10191022
version,
10201023
siteUri,
10211024
hash,
1022-
lock);
1025+
lock,
1026+
ss);
10231027

10241028
if (stats.bestDisposition() < result.bestDisposition() ||
10251029
(stats.bestDisposition() == result.bestDisposition() &&
@@ -1141,13 +1145,14 @@ ValidatorList::applyList(
11411145
std::uint32_t version,
11421146
std::string siteUri,
11431147
std::optional<uint256> const& hash,
1144-
ValidatorList::lock_guard const& lock)
1148+
ValidatorList::lock_guard const& lock,
1149+
std::unique_ptr<std::stringstream> const& ss)
11451150
{
11461151
using namespace std::string_literals;
11471152

11481153
Json::Value list;
11491154
auto const& manifest = localManifest ? *localManifest : globalManifest;
1150-
auto [result, pubKeyOpt] = verify(lock, list, manifest, blob, signature);
1155+
auto [result, pubKeyOpt] = verify(lock, list, manifest, blob, signature, ss);
11511156

11521157
if (!pubKeyOpt)
11531158
{
@@ -1356,17 +1361,31 @@ ValidatorList::verify(
13561361
Json::Value& list,
13571362
std::string const& manifest,
13581363
std::string const& blob,
1359-
std::string const& signature)
1364+
std::string const& signature,
1365+
std::unique_ptr<std::stringstream> const& ss)
13601366
{
13611367
auto m = deserializeManifest(base64_decode(manifest));
13621368

1363-
if (!m || !publisherLists_.count(m->masterKey))
1369+
if (!m || !publisherLists_.count(m->masterKey)) {
1370+
JLOG(j_.debug()) << "problem verifying manifest: deserialize "
1371+
<< (m ? "success" : "failure") << ", master key "
1372+
<< (publisherLists_.count(m->masterKey) ? "" : "not")
1373+
<< " in publisherLists_";
1374+
if (ss) {
1375+
*ss << "setting ListDisposition::untrusted. problem verifying manifest: deserialize "
1376+
<< (m ? "success" : "failure") << ", master key "
1377+
<< (publisherLists_.count(m->masterKey) ? "" : "not")
1378+
<< " in publisherLists_. ";
1379+
}
13641380
return {ListDisposition::untrusted, {}};
1381+
}
13651382

13661383
PublicKey masterPubKey = m->masterKey;
13671384
auto const revoked = m->revoked();
13681385

1369-
auto const result = publisherManifests_.applyManifest(std::move(*m));
1386+
auto applySs = std::make_unique<std::stringstream>();
1387+
auto const result = publisherManifests_.applyManifest(std::move(*m),
1388+
applySs);
13701389

13711390
if (revoked && result == ManifestDisposition::accepted)
13721391
{
@@ -1377,8 +1396,17 @@ ValidatorList::verify(
13771396

13781397
auto const signingKey = publisherManifests_.getSigningKey(masterPubKey);
13791398

1380-
if (revoked || !signingKey || result == ManifestDisposition::invalid)
1399+
if (revoked || !signingKey || result == ManifestDisposition::invalid) {
1400+
if (ss) {
1401+
*ss << "setting ListDisposition::untrusted. "
1402+
<< (revoked ? " revoked " : " not revoked ")
1403+
<< (signingKey ? "" : " bad signing key ")
1404+
<< (result == ManifestDisposition::invalid ? " invalid result. " : "");
1405+
if (!applySs->str().empty())
1406+
*ss << " reason: " << applySs->str() << ". ";
1407+
}
13811408
return {ListDisposition::untrusted, masterPubKey};
1409+
}
13821410

13831411
auto const sig = strUnHex(signature);
13841412
auto const data = base64_decode(blob);

‎src/xrpld/overlay/detail/ConnectAttempt.cpp‎

Lines changed: 29 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -51,14 +51,18 @@ ConnectAttempt::ConnectAttempt(
5151
, stream_(*stream_ptr_)
5252
, slot_(slot)
5353
{
54-
JLOG(journal_.debug()) << "Connect " << remote_endpoint;
54+
log << "CONNECTATTEMPT start " << to_string(std::chrono::system_clock::now())
55+
<< ". remote ip: " << remote_endpoint_ << ". id: " << id_;
56+
JLOG(journal_.debug()) << "connecting " << log.str();
5557
}
5658

5759
ConnectAttempt::~ConnectAttempt()
5860
{
5961
if (slot_ != nullptr)
6062
overlay_.peerFinder().on_closed(slot_);
6163
JLOG(journal_.trace()) << "~ConnectAttempt";
64+
JLOG(journal_.debug()) << log.str() << ". end reason: "
65+
<< (close_reason.str().empty() ? "unknown" : close_reason.str());
6266
}
6367

6468
void
@@ -71,7 +75,7 @@ ConnectAttempt::stop()
7175
{
7276
JLOG(journal_.debug()) << "Stop";
7377
}
74-
close();
78+
close("stop");
7579
}
7680

7781
void
@@ -88,7 +92,7 @@ ConnectAttempt::run()
8892
//------------------------------------------------------------------------------
8993

9094
void
91-
ConnectAttempt::close()
95+
ConnectAttempt::close(const char* reason)
9296
{
9397
XRPL_ASSERT(
9498
strand_.running_in_this_thread(),
@@ -99,21 +103,25 @@ ConnectAttempt::close()
99103
timer_.cancel(ec);
100104
socket_.close(ec);
101105
JLOG(journal_.debug()) << "Closed";
106+
log << "close ";
107+
close_reason << reason;
102108
}
103109
}
104110

105111
void
106112
ConnectAttempt::fail(std::string const& reason)
107113
{
108114
JLOG(journal_.debug()) << reason;
109-
close();
115+
close(reason.c_str());
110116
}
111117

112118
void
113119
ConnectAttempt::fail(std::string const& name, error_code ec)
114120
{
121+
std::stringstream ss;
122+
ss << name << ", error: " << ec.message();
115123
JLOG(journal_.debug()) << name << ": " << ec.message();
116-
close();
124+
close(ss.str().c_str());
117125
}
118126

119127
void
@@ -149,7 +157,9 @@ ConnectAttempt::onTimer(error_code ec)
149157
{
150158
// This should never happen
151159
JLOG(journal_.error()) << "onTimer: " << ec.message();
152-
return close();
160+
std::stringstream ss;
161+
ss << "onTimer, error: " << ec.message();
162+
return close(ss.str().c_str());
153163
}
154164
fail("Timeout");
155165
}
@@ -201,7 +211,7 @@ ConnectAttempt::onHandshake(error_code ec)
201211

202212
auto const sharedValue = makeSharedValue(*stream_ptr_, journal_);
203213
if (!sharedValue)
204-
return close(); // makeSharedValue logs
214+
return close("onHandshake no sharedValue"); // makeSharedValue logs
205215

206216
req_ = makeRequest(
207217
!overlay_.peerFinder().config().peerPrivate,
@@ -278,11 +288,11 @@ ConnectAttempt::onShutdown(error_code ec)
278288
if (!ec)
279289
{
280290
JLOG(journal_.error()) << "onShutdown: expected error condition";
281-
return close();
291+
return close("onShutdown: expected error condition");
282292
}
283293
if (ec != boost::asio::error::eof)
284294
return fail("onShutdown", ec);
285-
close();
295+
close("onShutdown eof");
286296
}
287297

288298
//--------------------------------------------------------------------------
@@ -331,7 +341,10 @@ ConnectAttempt::processResponse()
331341
JLOG(journal_.info())
332342
<< "Unable to upgrade to peer protocol: " << response_.result()
333343
<< " (" << response_.reason() << ")";
334-
return close();
344+
std::stringstream ss;
345+
ss << "unable to upgrade peer protocol: " << response_.result()
346+
<< " (" << response_.reason() << ")";
347+
return close(ss.str().c_str());
335348
}
336349

337350
// Just because our peer selected a particular protocol version doesn't
@@ -351,7 +364,7 @@ ConnectAttempt::processResponse()
351364

352365
auto const sharedValue = makeSharedValue(*stream_ptr_, journal_);
353366
if (!sharedValue)
354-
return close(); // makeSharedValue logs
367+
return close("processResponse no sharedValue"); // makeSharedValue logs
355368

356369
try
357370
{
@@ -365,14 +378,17 @@ ConnectAttempt::processResponse()
365378

366379
JLOG(journal_.info())
367380
<< "Public Key: " << toBase58(TokenType::NodePublic, publicKey);
381+
log << "public key: " << toBase58(TokenType::NodePublic, publicKey);
368382

369383
JLOG(journal_.debug())
370384
<< "Protocol: " << to_string(*negotiatedProtocol);
385+
log << " protocol: " << to_string(*negotiatedProtocol);
371386

372387
auto const member = app_.cluster().member(publicKey);
373388
if (member)
374389
{
375390
JLOG(journal_.info()) << "Cluster name: " << *member;
391+
log << "cluster name: " << *member;
376392
}
377393

378394
auto const result = overlay_.peerFinder().activate(
@@ -391,13 +407,15 @@ ConnectAttempt::processResponse()
391407
*negotiatedProtocol,
392408
id_,
393409
overlay_);
410+
peer->log << "outbound ( " << log.str() << "). ";
394411

395412
overlay_.add_active(peer);
396413
}
397414
catch (std::exception const& e)
398415
{
399416
return fail(std::string("Handshake failure (") + e.what() + ")");
400417
}
418+
close_reason << "successful connection";
401419
}
402420

403421
} // namespace ripple

‎src/xrpld/overlay/detail/ConnectAttempt.h‎

Lines changed: 5 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -22,6 +22,7 @@
2222

2323
#include <xrpld/overlay/detail/OverlayImpl.h>
2424
#include <xrpld/overlay/detail/Tuning.h>
25+
#include <sstream>
2526

2627
namespace ripple {
2728

@@ -62,6 +63,9 @@ class ConnectAttempt : public OverlayImpl::Child,
6263
request_type req_;
6364

6465
public:
66+
std::stringstream log;
67+
std::stringstream close_reason;
68+
6569
ConnectAttempt(
6670
Application& app,
6771
boost::asio::io_service& io_service,
@@ -83,7 +87,7 @@ class ConnectAttempt : public OverlayImpl::Child,
8387

8488
private:
8589
void
86-
close();
90+
close(const char* reason);
8791
void
8892
fail(std::string const& reason);
8993
void

0 commit comments

Comments
 (0)