Added ping time measurement. #2937

New RPC "ping" command to request ping. Implemented "pong" message handler. New "pingtime" field in getpeerinfo, to provide results to user.

We've been having a fine discussion here: https://bitcointalk.org/index.php?topic=279652.0

Seems like an awful lot of code for one simple feature... no technical objection but... meh. I would rather a simple hook system (boost signals?) that delivers a pong response, to anyone who pre-registers a pong handler for nonce X. That would keep most of the code more in the RPC side of things.

Thanks for the feedback. It did end up being more code than I thought it would. Reason is, there's 3 different protocol variations to contend with (no nonce, zero nonce, matching nonce). Also, there was no pong receiver at all, so had to add that as well.

I added a good amount of debug text in "if (fDebug) ..." blocks, which is rather verbose. I'm surprised there's no dprintf() or similar macro, perhaps there's something I missed. Every debug line adds another possible code path, because of that if statement. Probably the lowest-hanging fruit is to jettison those.

I wonder how a hook system would work? Registering a handler would seem to complicate things even more. The ping and pong messages have to be sent/received anyway, that would just add another layer of indirection to shift the processing elsewhere, unless there's something I'm missing here.

ACK.

It's perhaps slightly over-complicated (rate-limiting user-requested pings?), but it's otherwise pretty much how I'd have suggested implementing it.

One nit: the ping RPC command could be a separate commit from the rest of the logic, but I don't feel strongly about this.

@jgarzik Agree that a hook-mechanism for dealing with incoming commands is probably the future, but we don't do that right now for other messages, and it's unreasonable to demand that in a pullreq like this.

Thanks for the feedback.

I will remove the ratelimit for user-requested outbound pings, since you're right, that does seem rather overcomplicated.

Also, good catch on indentation, I didn't see that. Darn editor :)

It is strange to see a ping with a valid nonce be replied to with a pong with a nonce of 0. However, this is very common on the wire, I have noticed. I looked through the history but could not find it. I'm guessing it's another implementation that has this bug?

I like the idea of only accepting these weird pong replies (nonce of zero) if that implementation can be detected. What distinguishes it? Unfortunately, I don't think its protocol version gives it away.

I updated the commit.

Got rid of the idea of rate-limiting user-requested RPC pings, that simplifies a chunk of code.

Cleaned up indentation.

The "pingtime" field shows only completed pings. I took the liberty of adding a second field, "pingwait", that will only appear during the time a ping is in flight. It will show you how long we have been waiting for that ping to complete. This gives a window of visibility into noticing a sudden increase in lag (perhaps a newly solved block just arrived), or a peer that is so burdened that it is having trouble responding to pings.

I could put this patch on a diet by jettisoning the debugging/error messages for various things that can happen. Good or bad idea? The messages were useful during testing but it's pretty much solid now.

Why reinvent '/sbin/ping' ? Why not just a little shell script that calls getpeerinfo, then uses the system ping to determine ping times?

I'm a less-code-is-better kinda guy.

@gavinandresen There are many factors that affect Bitcoin P2P latency which you wouldn't notice through network-level ping (application throttling, peer having an overloaded receive queue, peer being DoS'ed, implementation problems...), and it will not work for every type of connection (incoming peers that are firewalled, or onion peers for example).

Additionally, having ping statistics inside the program can be useful for future heuristics when picking peers to sync/download from.

Thanks sipa, very well said. That's the key reasons to have a ping at the Bitcoin layer, not just at the OS networking layer.

I have put the ping/pong handlers in main.cpp on a diet. Removed the printf statements, they have proved their usefulness during testing, but don't need to be in there permanently.

future heuristics when picking peers to sync/download from.

Also for picking peers to keep/discard when our connection slots are full: Low latency is something that a sibyl attacker can't just fake— he actually has to get close to you—, so it makes sense to full to reserve some slots for the lowest latency, apparently healthy peers.

Thanks. As talked about on IRC the other night, I restored some code that was in the before, to drop pong messages if they are received with a nonce of zero. I am unsure what clients are sending these. Their version string comes across as "0.8.99" but I haven't found any version history that would ever send a pong (not a ping!) with a nonce of zero.

While running it overnight, I noticed yet another bad client pong behavior. The peer is sending me pong messages with no payload at all (zero bytes). This causes an exception during unserialize, which is caught so nothing harmful happens, but it's unclean.

What are the subVers of the bad clients?

Investigating that now. Frustratingly, it isn't happening anymore with my current set of peers that I'm connected to.

Made some changes.

1. Added more instrumentation to catch all of the anomalies that we've seen so far, in the pong handler. Instead of previous bloat, they are all now unified into a single printf statement.

2. Incoming pong message size is now checked. Unfortunately, I did not find any more peers who were giving me those empty-payload pong messages, but if they show up again, they will be cleanly logged this time, instead of throwing the exception. I noticed in_avail() in serialize.h returns an int. Shouldn't it be a size_t? There are no other users of it in bitcoind, I have noticed.

3. I just now call RAND_bytes() for each peer, instead of trying to save random entropy by only calling it once per overall ping request and then just incrementing it for each peer. Should now never be guessable, but at the cost of burning the entropy pool. Perhaps use RAND_pseudo_bytes() instead?

Also, this pull request is getting somewhat long in the tooth. I ran it against the latest top of tree, and it still applies cleanly and works just fine. Should I close this pull request and make a new pull request from a branch closer to the very latest, or keep this pull request open?

Tested against latest top of tree and patch still applies cleanly.

Rebased the branch to catch up to latest master.

ACK

@jgarzik @gavinandresen @gmaxwell Any further comments? I'd like this merged, to be able to add some automatic latency measurement on top.

s/printf(/LogPrint("net"/ and I'm OK with merging.

Great idea to use LogPrint instead. Made that one-line change. Also rebased it against the latest master.

Fixed the merge. The "ping" command doesn't require access to the wallet, of course, so the new column is false for it.

Automatic sanity-testing: PASSED, see http://jenkins.bluematt.me/pull-tester/971bb3e901aad5d4f04a651e3e2a75161d3a4e2a for binaries and test log. This test script verifies pulls every time they are updated. It, however, dies sometimes and fails to test properly. If you are waiting on a test, please check timestamps to verify that the test.log is moving at http://jenkins.bluematt.me/pull-tester/current/ Contact BlueMatt on freenode if something looks broken.