[
https://issues.apache.org/jira/browse/ZOOKEEPER-2471?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16137090#comment-16137090
]
Nick Travers commented on ZOOKEEPER-2471:
-----------------------------------------
Thanks for the response [~dbenediktson]. Re-reading your comments, I just can't
seem to replicate the case you talk about where a client gets stuck in a
reconnect loop.
Here's how I'm testing this:
- introduce an artificially high sleep time (say 5 seconds), replacing the
random timeout in the client
[here|https://github.com/apache/zookeeper/blob/release-3.5.3/src/java/main/org/apache/zookeeper/ClientCnxn.java#L1059],
via what is essentially a crude patch for ZOOKEEPER-2869
- Set up an ensemble of 5 ZK servers
- Set up a client with an artificially low connect timeout of 1 second, as you
describe. Wait for an initial client connection to be established
- Trigger a leader re-election by restarting the current leader
- At this point, the client sleeps for the artificially long timeout for a few
cycles through the loop, until the leader has been re-elected
- Ultimately, the client is able to reconnect
I'm not observing the infinite reconnect loop you describe.
In my mind it makes more sense to be able to observe this bug first before
trying to patch it, and that seems to come up only _after_ introducing a fix
for ZOOKEEPER-2869.
What do you think about opening an additional PR for ZOOKEEPER-2869 so we can
try to more easily reproduce the bug for ZOOKEEPER-2471? At that point the test
scaffolding will be in place to make this task much easier.
> Java Zookeeper Client incorrectly considers time spent sleeping as time spent
> connecting, potentially resulting in infinite reconnect loop
> ------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: ZOOKEEPER-2471
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-2471
> Project: ZooKeeper
> Issue Type: Bug
> Components: java client
> Affects Versions: 3.5.3
> Environment: all
> Reporter: Dan Benediktson
> Assignee: Dan Benediktson
> Attachments: ZOOKEEPER-2471.patch
>
>
> ClientCnxnSocket uses a member variable "now" to track the current time, and
> lastSend / lastHeard variables to track socket liveness. Implementations, and
> even ClientCnxn itself, are expected to call both updateNow() to reset "now"
> to System.currentTimeMillis, and then call updateLastSend()/updateLastHeard()
> on IO completions.
> This is a fragile contract, so it's not surprising that there's a bug
> resulting from it: ClientCnxn.SendThread.run() calls updateLastSendAndHeard()
> as soon as startConnect() returns, but it does not call updateNow() first. I
> expect when this was written, either the expectation was that startConnect()
> was an asynchronous operation and that updateNow() would have been called
> very recently, or simply the requirement to call updateNow() was forgotten at
> this point. As far as I can see, this bug has been present since the
> "updateNow" method was first introduced in the distant past. As it turns out,
> since startConnect() calls HostProvider.next(), which can sleep, quite a lot
> of time can pass, leaving a big gap between "now" and now.
> If you are using very short session timeouts (one of our ZK ensembles has
> many clients using a 1-second timeout), this is potentially disastrous,
> because the sleep time may exceed the connection timeout itself, which can
> potentially result in the Java client being stuck in a perpetual reconnect
> loop. The exact code path it goes through in this case is complicated,
> because there has to be a previously-closed socket still waiting in the
> selector (otherwise, the first timeout evaluation will not fail because "now"
> still hasn't been updated, and then the actual connect timeout will be
> applied in ClientCnxnSocket.doTransport()) so that select() will harvest the
> IO from the previous socket and updateNow(), resulting in the next loop
> through ClientCnxnSocket.SendThread.run() observing the spurious timeout and
> failing. In practice it does happen to us fairly frequently; we only got to
> the bottom of the bug yesterday. Worse, when it does happen, the Zookeeper
> client object is rendered unusable: it's stuck in a perpetual reconnect loop
> where it keeps sleeping, opening a socket, and immediately closing it.
> I have a patch. Rather than calling updateNow() right after startConnect(),
> my fix is to remove the "now" member variable and the updateNow() method
> entirely, and to instead just call System.currentTimeMillis() whenever time
> needs to be evaluated. I realize there is a benefit (aside from a trivial
> micro-optimization not worth worrying about) to having the time be "fixed",
> particularly for truth in the logging: if time is fixed by an updateNow()
> call, then the log for a timeout will still show exactly the same value the
> code reasoned about. However, this benefit is in my opinion not enough to
> merit the fragility of the contract which led to this (for us) highly
> impactful and difficult-to-find bug in the first place.
> I'm currently running ant tests locally against my patch on trunk, and then
> I'll upload it here.
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
