[ZOOKEEPER-4028] zookeeper client timeout

• Type: Bug
• Status: Resolved
• Priority: Trivial
• Resolution: Invalid

Environment

2020-12-14 20:09:43,488 [myid:] - WARN [NIOWorkerThread-2:NIOServerCnxn@366] - Unable to read additional data from client sessionid 0x10000989ff10001, likely client has closed socket
4.I expected after 2000ms(2s) zookeeper should set the session timetout, but zookeeper set the session timeout state after 17s has pased! I don't know why. anyone has suggestion?
2020-12-14 20:08:07,309 [myid:] - INFO [main:ZooKeeperServer@947] - maxSessionTimeout set to 20000
2020-12-14 20:08:07,309 [myid:] - INFO [main:ZooKeeperServer@166] - Created server with tickTime 1000 minSessionTimeout 2000 maxSessionTimeout 20000 datadir /tmp/zookeeper/version-2 snapdir /tmp/zookeeper/version-2
2020-12-14 20:08:07,321 [myid:] - INFO [main:Log@169] - Logging initialized @296ms to org.eclipse.jetty.util.log.Slf4jLog
2020-12-14 20:08:07,384 [myid:] - WARN [main:ContextHandler@1520] - o.e.j.s.ServletContextHandler@57536d79

{/,null,UNAVAILABLE}

contextPath ends with /*
2020-12-14 20:08:07,385 [myid:] - WARN [main:ContextHandler@1531] - Empty contextPath
2020-12-14 20:08:07,394 [myid:] - INFO [main:Server@359] - jetty-9.4.24.v20191120; built: 2019-11-20T21:37:49.771Z; git: 363d5f2df3a8a28de40604320230664b9c793c16; jvm 1.8.0_261-b12
2020-12-14 20:08:07,427 [myid:] - INFO [main:DefaultSessionIdManager@333] - DefaultSessionIdManager workerName=node0
2020-12-14 20:08:07,427 [myid:] - INFO [main:DefaultSessionIdManager@338] - No SessionScavenger set, using defaults
2020-12-14 20:08:07,429 [myid:] - INFO [main:HouseKeeper@140] - node0 Scavenging every 660000ms
2020-12-14 20:08:07,436 [myid:] - INFO [main:ContextHandler@825] - Started o.e.j.s.ServletContextHandler@57536d79

{/,null,AVAILABLE}

2020-12-14 20:08:07,444 [myid:] - INFO [main:AbstractConnector@330] - Started ServerConnector@1e88b3c

{HTTP/1.1,[http/1.1]} {0.0.0.0:8080}

2020-12-14 20:08:07,444 [myid:] - INFO [main:Server@399] - Started @419ms
2020-12-14 20:08:07,444 [myid:] - INFO [main:JettyAdminServer@112] - Started AdminServer on address 0.0.0.0, port 8080 and command URL /commands
2020-12-14 20:08:07,447 [myid:] - INFO [main:ServerCnxnFactory@135] - Using org.apache.zookeeper.server.NIOServerCnxnFactory as server connection factory
2020-12-14 20:08:07,448 [myid:] - INFO [main:NIOServerCnxnFactory@673] - Configuring NIO connection handler with 10s sessionless connection timeout, 1 selector thread(s), 4 worker threads, and 64 kB direct buffers.
2020-12-14 20:08:07,449 [myid:] - INFO [main:NIOServerCnxnFactory@686] - binding to port 0.0.0.0/0.0.0.0:2181
2020-12-14 20:08:07,457 [myid:] - INFO [main:ZKDatabase@117] - zookeeper.snapshotSizeFactor = 0.33
2020-12-14 20:08:07,459 [myid:] - INFO [main:FileSnap@83] - Reading snapshot /tmp/zookeeper/version-2/snapshot.aa
2020-12-14 20:08:07,470 [myid:] - INFO [main:FileTxnSnapLog@404] - Snapshotting: 0xbb to /tmp/zookeeper/version-2/snapshot.bb
2020-12-14 20:08:07,480 [myid:] - INFO [main:ContainerManager@64] - Using checkIntervalMs=60000 maxPerMinute=10000
2020-12-14 20:08:22,412 [myid:] - INFO [SyncThread:0:FileTxnLog@218] - Creating new log file: log.bc
2020-12-14 20:08:28,055 [myid:] - INFO [SessionTracker:ZooKeeperServer@398] - Expiring session 0x1000091408c0000, timeout of 20000ms exceeded
2020-12-14 20:08:43,210 [myid:] - WARN [NIOWorkerThread-1:NIOServerCnxn@366] - Unable to read additional data from client sessionid 0x10000989ff10000, likely client has closed socket
2020-12-14 20:09:03,057 [myid:] - INFO [SessionTracker:ZooKeeperServer@398] - Expiring session 0x10000989ff10000, timeout of 20000ms exceeded
2020-12-14 20:09:07,482 [myid:] - INFO [ContainerManagerTask:ContainerManager@119] - Attempting to delete candidate container: /msg/root/msg3
2020-12-14 20:09:07,488 [myid:] - INFO [ContainerManagerTask:ContainerManager@119] - Attempting to delete candidate container: /msg/root/msg1
2020-12-14 20:09:07,495 [myid:] - INFO [ContainerManagerTask:ContainerManager@119] - Attempting to delete candidate container: /msg/root/msg2
2020-12-14 20:09:43,488 [myid:] - WARN [NIOWorkerThread-2:NIOServerCnxn@366] - Unable to read additional data from client sessionid 0x10000989ff10001, likely client has closed socket
2020-12-14 20:10:00,056 [myid:] - INFO [SessionTracker:ZooKeeperServer@398] - Expiring session 0x10000989ff10001, timeout of 20000ms exceeded
2020-12-14 20:10:07,481 [myid:] - INFO [ContainerManagerTask:ContainerManager@119] - Attempting to delete candidate container: /msg/root/msg3
2020-12-14 20:10:07,487 [myid:] - INFO [ContainerManagerTask:ContainerManager@119] - Attempting to delete candidate container: /msg/root/msg1
2020-12-14 20:10:07,494 [myid:] - INFO [ContainerManagerTask:ContainerManager@119] - Attempting to delete candidate container: /msg/root/msg2
2020-12-14 20:11:07,482 [myid:] - INFO [ContainerManagerTask:ContainerManager@119] - Attempting to delete candidate container: /msg/root
2020-12-14 20:12:07,483 [myid:] - INFO [ContainerManagerTask:ContainerManager@119] - Attempting to delete candidate container: /msg
lyd@ubuntu:~/run_space/apache-zookeeper-3.5.8-bin/logs$

• Assignee: Unassigned
• Reporter: LYD
• Created: 14/Dec/20 12:44
• Updated: 15/Jan/21 10:58
• Resolved: 15/Jan/21 10:58

Description

I test like this(configure: tickTime=1000):
1.connect to the zookeeper server with timeout 2000ms;
2.kill client, the client log shows be killed at 20:09:43
3.check zookeeper log, almost at the same time, zookeeper touch the socket issue:
2020-12-14 20:09:43,488 [myid:] - WARN [NIOWorkerThread-2:NIOServerCnxn@366] - Unable to read additional data from client sessionid 0x10000989ff10001, likely client has closed socket
4.I expected after 2000ms(2s) zookeeper should set the session timetout, but zookeeper set the session timeout state after 17s has pased! I don't know why. anyone has suggestion?