LYD created ZOOKEEPER-4028:
------------------------------
Summary: zookeeper client timeout
Key: ZOOKEEPER-4028
URL: https://issues.apache.org/jira/browse/ZOOKEEPER-4028
Project: ZooKeeper
Issue Type: Bug
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$
Reporter: LYD
Attachments: QQ截图20201214203717.png
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?
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
