zookeeper-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Jan-Philip Gehrcke (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (ZOOKEEPER-3466) ZK cluster converges, but does not properly handle client connections (new in 3.5.5)
Date Wed, 24 Jul 2019 09:22:00 GMT

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

Jan-Philip Gehrcke commented on ZOOKEEPER-3466:
-----------------------------------------------

Thanks for having a look, Michael.

{quote}
is the problem being that clients can't connect to the ensemble,
{quote}
This (cf. point 6 in the description above). To clarify, the problem exists in a freshly set
up 3.5.5 ZooKeeper ensemble.

{quote}
If it's ok to disclose the log files for both server and client,
{quote}
Relevant client log is above, but let me put it into a code block with a tiny bit more context


{code:java}
Python 3.6.8 (default, Jun 26 2019, 00:07:55) 
[GCC 4.8.5] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import kazoo
>>> from kazoo.client import KazooClient
>>> zk = KazooClient(hosts='127.0.0.1:2181')
>>> zk.start()
Connection time-out: socket time-out during read
{code}

Relevant server log on TRACE level, with my annotations :
{code}
# There is a bit of history before this log snippet, but it's not much.
# It's a "fresh" ZooKeeper ensemble managed by Exhibitor.
# The current ZooKeeper instance (of which we see the logs)
# was restarted two or three times.

[...]

# Shortly before this  the last leader election was triggered
# Here, the current ZooKeeper instance (of which we see the log)
# was just elected leader. It has two followers

Jul 23 14:38:07 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] INFO  [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Leader@1296]
- Have quorum of supporters, sids: [ [1, 2, 3],[1, 2] ]; starting up and setting last processed
zxid: 0x200000000
Jul 23 14:38:07 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] DEBUG [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):QuorumPeer@1934]
- Reconfig feature is disabled, skip reconfig processing.
Jul 23 14:38:07 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] INFO  [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):CommitProcessor@256]
- Configuring CommitProcessor with 8 worker threads.
Jul 23 14:38:07 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] INFO  [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):ContainerManager@64]
- Using checkIntervalMs=60000 maxPerMinute=10000
Jul 23 14:38:07 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] DEBUG [LearnerHandler-/172.17.0.5:58670:LearnerHandler@534]
- Sending UPTODATE message to 2
Jul 23 14:38:07 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] DEBUG [LearnerHandler-/172.17.0.3:52126:LearnerHandler@534]
- Sending UPTODATE message to 1
Jul 23 14:38:07 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] TRACE [Sender-/172.17.0.3:52126:ZooTrace@71]
- o UPTODATE ffffffffffffffff null
Jul 23 14:38:07 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] TRACE [Sender-/172.17.0.5:58670:ZooTrace@71]
- o UPTODATE ffffffffffffffff null
Jul 23 14:38:07 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] TRACE [LearnerHandler-/172.17.0.5:58670:ZooTrace@71]
- i ACK 200000000 null
Jul 23 14:38:07 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] TRACE [LearnerHandler-/172.17.0.3:52126:ZooTrace@71]
- i ACK 200000000 null

# The local Exhibitor (supervisor of this ZK instance) sends ruok and srvr commands

Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] DEBUG [NIOServerCxnFactory.AcceptThread:/0.0.0.0:2181:NIOServerCnxnFactory$AcceptThread@296]
- Accepted socket connection from /127.0.0.1:37620
Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] INFO  [NIOWorkerThread-3:NIOServerCnxn@518]
- Processing ruok command from /127.0.0.1:37620
Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] DEBUG [NIOWorkerThread-3:NIOServerCnxn@627]
- Closed socket connection for client /127.0.0.1:37620 (no session established for client)
Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] DEBUG [NIOServerCxnFactory.AcceptThread:/0.0.0.0:2181:NIOServerCnxnFactory$AcceptThread@296]
- Accepted socket connection from /127.0.0.1:37622
Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] INFO  [NIOWorkerThread-4:NIOServerCnxn@518]
- Processing srvr command from /127.0.0.1:37622
Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] DEBUG [NIOWorkerThread-4:NIOServerCnxn@627]
- Closed socket connection for client /127.0.0.1:37622 (no session established for client)

# The next log line is emitted by Exhibitor (Exhibitor and ZK logs are interleaved),
# it confirms that Exhibitor saw expected RUOK and SRVR feedback.

Jul 23 14:38:35 dcos-e2e-9af6b-master-1 start_exhibitor.py[1307]: INFO  com.netflix.exhibitor.core.activity.ActivityLog
 State: serving [ActivityQueue-0]

# Now that Exhibitor "thinks" that ZooKeeper is healthy the ZK clients try to connect
# (to all three nodes in the ZK ensemble).

Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] TRACE [LearnerHandler-/172.17.0.3:52126:ZooTrace@71]
- i REQUEST ffffffffffffffff null
Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] TRACE [ProcessThread(sid:3 cport:-1)::ZooTrace@88]
- :Psessionid:0x1000ac8b67e0000 type:createSession cxid:0x0 zxid:0xfffffffffffffffe txntype:unknown
reqpath:n/a
Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] DEBUG [ProcessThread(sid:3 cport:-1)::SessionTrackerImpl@274]
- Adding session 0x1000ac8b67e0000
Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] TRACE [ProcessThread(sid:3 cport:-1)::ZooTrace@71]
- SessionTrackerImpl --- Adding session 0x1000ac8b67e0000 10000
Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] DEBUG [ProcessThread(sid:3 cport:-1)::CommitProcessor@344]
- Processing request:: sessionid:0x1000ac8b67e0000 type:createSession cxid:0x0 zxid:0x200000001
txntype:-10 reqpath:n/a
Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] DEBUG [ProcessThread(sid:3 cport:-1)::Leader@1114]
- Proposing:: sessionid:0x1000ac8b67e0000 type:createSession cxid:0x0 zxid:0x200000001 txntype:-10
reqpath:n/a
Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] INFO  [SyncThread:3:FileTxnLog@216]
- Creating new log file: log.200000001
Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] TRACE [LearnerHandler-/172.17.0.5:58670:ZooTrace@71]
- i ACK 200000001 null
Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] TRACE [LearnerHandler-/172.17.0.3:52126:ZooTrace@71]
- i ACK 200000001 null
Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] DEBUG [NIOServerCxnFactory.AcceptThread:/0.0.0.0:2181:NIOServerCnxnFactory$AcceptThread@296]
- Accepted socket connection from /127.0.0.1:37630
Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] DEBUG [NIOWorkerThread-5:ZooKeeperServer@1001]
- Session establishment request from client /127.0.0.1:37630 client's lastZxid is 0x0
Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] DEBUG [NIOWorkerThread-5:SessionTrackerImpl@274]
- Adding session 0x3000ac8b6c50000
Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] TRACE [NIOWorkerThread-5:ZooTrace@71]
- SessionTrackerImpl --- Adding session 0x3000ac8b6c50000 10000
Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] TRACE [ProcessThread(sid:3 cport:-1)::ZooTrace@88]
- :Psessionid:0x3000ac8b6c50000 type:createSession cxid:0x0 zxid:0xfffffffffffffffe txntype:unknown
reqpath:n/a
Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] TRACE [ProcessThread(sid:3 cport:-1)::ZooTrace@71]
- SessionTrackerImpl --- Existing session 0x3000ac8b6c50000 10000
Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] DEBUG [ProcessThread(sid:3 cport:-1)::CommitProcessor@344]
- Processing request:: sessionid:0x3000ac8b6c50000 type:createSession cxid:0x0 zxid:0x200000002
txntype:-10 reqpath:n/a
Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] DEBUG [ProcessThread(sid:3 cport:-1)::Leader@1114]
- Proposing:: sessionid:0x3000ac8b6c50000 type:createSession cxid:0x0 zxid:0x200000002 txntype:-10
reqpath:n/a
Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] DEBUG [NIOWorkerThread-5:ZooKeeperServer@1052]
- Client attempting to establish new session: session = 0x3000ac8b6c50000, zxid = 0x0, timeout
= 10000, address = /127.0.0.1:37630
Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] TRACE [LearnerHandler-/172.17.0.3:52126:ZooTrace@71]
- i ACK 200000002 null
Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] TRACE [LearnerHandler-/172.17.0.5:58670:ZooTrace@71]
- i ACK 200000002 null
Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] TRACE [LearnerHandler-/172.17.0.5:58670:ZooTrace@71]
- i REQUEST ffffffffffffffff null
Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] TRACE [ProcessThread(sid:3 cport:-1)::ZooTrace@88]
- :Psessionid:0x2000ac8b60f0000 type:createSession cxid:0x0 zxid:0xfffffffffffffffe txntype:unknown
reqpath:n/a
Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] DEBUG [ProcessThread(sid:3 cport:-1)::SessionTrackerImpl@274]
- Adding session 0x2000ac8b60f0000
Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] TRACE [ProcessThread(sid:3 cport:-1)::ZooTrace@71]
- SessionTrackerImpl --- Adding session 0x2000ac8b60f0000 10000
Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] DEBUG [ProcessThread(sid:3 cport:-1)::CommitProcessor@344]
- Processing request:: sessionid:0x2000ac8b60f0000 type:createSession cxid:0x0 zxid:0x200000003
txntype:-10 reqpath:n/a
Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] DEBUG [ProcessThread(sid:3 cport:-1)::Leader@1114]
- Proposing:: sessionid:0x2000ac8b60f0000 type:createSession cxid:0x0 zxid:0x200000003 txntype:-10
reqpath:n/a
Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] TRACE [LearnerHandler-/172.17.0.3:52126:ZooTrace@71]
- i ACK 200000003 null
Jul 23 14:38:35 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] TRACE [LearnerHandler-/172.17.0.5:58670:ZooTrace@71]
- i ACK 200000003 null
Jul 23 14:38:36 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] DEBUG [NIOServerCxnFactory.AcceptThread:/0.0.0.0:2181:NIOServerCnxnFactory$AcceptThread@296]
- Accepted socket connection from /127.0.0.1:37636
Jul 23 14:38:36 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] DEBUG [NIOWorkerThread-6:ZooKeeperServer@1001]
- Session establishment request from client /127.0.0.1:37636 client's lastZxid is 0x0
Jul 23 14:38:36 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] DEBUG [NIOWorkerThread-6:SessionTrackerImpl@274]
- Adding session 0x3000ac8b6c50001
Jul 23 14:38:36 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] TRACE [NIOWorkerThread-6:ZooTrace@71]
- SessionTrackerImpl --- Adding session 0x3000ac8b6c50001 10000
Jul 23 14:38:36 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] TRACE [ProcessThread(sid:3 cport:-1)::ZooTrace@88]
- :Psessionid:0x3000ac8b6c50001 type:createSession cxid:0x0 zxid:0xfffffffffffffffe txntype:unknown
reqpath:n/a
Jul 23 14:38:36 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] TRACE [ProcessThread(sid:3 cport:-1)::ZooTrace@71]
- SessionTrackerImpl --- Existing session 0x3000ac8b6c50001 10000
Jul 23 14:38:36 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] DEBUG [ProcessThread(sid:3 cport:-1)::CommitProcessor@344]
- Processing request:: sessionid:0x3000ac8b6c50001 type:createSession cxid:0x0 zxid:0x200000004
txntype:-10 reqpath:n/a
Jul 23 14:38:36 dcos-e2e-9af6b-master-1 java[9048]: [myid:3] DEBUG [ProcessThread(sid:3 cport:-1)::Leader@1114]
- Proposing:: sessionid:0x3000ac8b6c50001 type:createSession cxid:0x0 zxid:0x200000004 txntype:-10
reqpath:n/a

...
{code}

The server log above corresponds to client(s) not getting bytes on the TCP connection (resulting
in timeout errors).

{quote}
It would be also helpful to have a relatively straight forward reproduce steps with detailed
version and configuration information for both server and clients.
{quote}
Yes, I can imagine and I would love to be able to provide a simple repro. However, I could
only see this so far when Exhibitor coordinates ZooKeeper through a dynamic ensemble which
involves another ZooKeeper or S3. Personally I do have a repro, but it is still too complex
to share ... it involves a DC/OS cluster started in various Docker containers and a coordination
ZooKeeper instance (through which the individual Exhibitor instances coordinate themselves).
They key insight from this repro environment is that the exact same setup works fine with
ZooKeeper 3.4.14, but breaks often (not always) with ZooKeeper 3.5.5.

> ZK cluster converges, but does not properly handle client connections (new in 3.5.5)
> ------------------------------------------------------------------------------------
>
>                 Key: ZOOKEEPER-3466
>                 URL: https://issues.apache.org/jira/browse/ZOOKEEPER-3466
>             Project: ZooKeeper
>          Issue Type: Bug
>    Affects Versions: 3.5.5
>         Environment: Linux
>            Reporter: Jan-Philip Gehrcke
>            Priority: Major
>
> Hey, we explore switching from ZooKeeper 3.4.14 to ZooKeeper 3.5.5 in [https://github.com/dcos/dcos].
> DC/OS coordinates ZooKeeper via Exhibitor. We are not changing anything w.r.t. Exhibitor
for now, and are hoping that we can use ZooKeeper 3.5.5 as a drop-in replacement for 3.4.14.
This seems to work fine when Exhibitor uses a so-called static ensemble where the individual
ZooKeeper instances are known a priori.
> When Exhibitor however discovers individual ZooKeeper instances ("dynamic" back-end)
then I think we observe a regression where ZooKeeper 3.5.5 can get into the following bad
state (often, but not always):
>  # three ZooKeeper instances find each other, leader election takes place (*expected*)
>  # leader election succeeds: two followers, one leader (*expected*)
>  # all three ZK instances respond IAMOK to RUOK  (*expected*)
>  # all three ZK instances respond to SRVR (one says "Mode: leader", the other two say
"Mode: follower")  (*expected*)
>  # all three ZK instances respond to MNTR and show plausible output (*expected*)
>  # *{color:#ff0000}Unexpected:{color}* any ZooKeeper client trying to connect to any
of the three nodes observes a "connection timeout", whereas notably this is *not* a TCP connect()
timeout. The TCP connect() succeeds, but then ZK does not seem to send the expected byte sequence
to the TCP connection, and the ZK client waits for it via recv() until it hits a timeout condition.
Examples for two different clients:
>  ## In Kazoo we specifically hit _Connection time-out: socket time-out during read_
>  generated here: [https://github.com/python-zk/kazoo/blob/88b657a0977161f3815657878ba48f82a97a3846/kazoo/protocol/connection.py#L249]
>  ## In zkCli we see  _Client session timed out, have not heard from server in 15003ms
for sessionid 0x0, closing socket connection and attempting reconnect (org.apache.zookeeper.ClientCnxn:main-SendThread(localhost:2181))_
>  # This state is stable, it will last forever (well, at least for multiple hours and
we didn't test longer than that).
>  # In our system the ZooKeeper clients are crash-looping. They retry. What I have observed
is that while they retry the ZK ensemble accumulates outstanding requests, here shown from
MNTR output (emphasis mine): 
>  zk_packets_received 2008
>  zk_packets_sent 127
>  zk_num_alive_connections 18
>  zk_outstanding_requests *1880*
>  # The leader emits log lines confirming session timeout, example:
>  _[myid:3] INFO [SessionTracker:ZooKeeperServer@398] - Expiring session 0x2000642b18f0020,
timeout of 10000ms exceeded [myid:3] INFO [SessionTracker:QuorumZooKeeperServer@157] - Submitting
global closeSession request for session 0x2000642b18f0020_
>  # In this state, restarting any one of the two ZK followers results in the same state
(clients don't get data from ZK upon connect).
>  # In this state, restarting the ZK leader, and therefore triggering a leader re-election,
almost immediately results in all clients being able to connect to all ZK instances successfully.



--
This message was sent by Atlassian JIRA
(v7.6.14#76016)

Mime
View raw message