zookeeper-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "ASF GitHub Bot (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (ZOOKEEPER-2471) Java Zookeeper Client incorrectly considers time spent sleeping as time spent connecting, potentially resulting in infinite reconnect loop
Date Fri, 18 Aug 2017 17:17:00 GMT

    [ https://issues.apache.org/jira/browse/ZOOKEEPER-2471?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16133300#comment-16133300
] 

ASF GitHub Bot commented on ZOOKEEPER-2471:
-------------------------------------------

Github user nicktrav commented on the issue:

    https://github.com/apache/zookeeper/pull/330
  
    Feels a little awkward to have a non-trivial change without any tests :/
    
    > I'm still going to be stuck depending on the behavior of that randomly-generated
sleep time, which is going to be inherently unreliable
    
    Thinking aloud here ... given your second commit updates to use the `Time` utility, could
you now inject that class, (or perhaps a faked implementation given the methods are static),
into `ClientCnxnSocket` and its subclasses? This would make it more amenable to testing. You'd
have more control over the times that are returned.
    
    You'd still need to plumb that through into `ClientCnxn`, but it looks like the constructor
takes a `ClientCnxnSocket`, which could work here?
    
    Maybe we can get that scaffolding wired up in another PR, get that merged in, and this
change could leverage that?


> 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)

Mime
View raw message