Hello Enrico,
thanks for the reply. I'll try to find the exception, there was none
around 14:50 when it first appeared. I also try to find the client
that's connecting just before that as it's not a Kafka-node:
Oct 21 14:50:31 zookeeper_node_3: 2019-10-21 01:50:31,532 [myid:3] -
INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@222] -
Accepted socket connection from /10.24.8.13:64261
Oct 21 14:50:31 zookeeper_node_3: 2019-10-21 01:50:31,544 [myid:3] -
WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@383] -
Exception causing close of session 0x0: null
Oct 21 14:50:31 zookeeper_node_3: 2019-10-21 01:50:31,545 [myid:3] -
INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1056] -
Closed socket connection for client /10.24.8.13:64261 (no session
established for client)
The same IP is able to connect to Zookeeper successfully some time before:
Oct 21 13:18:44 zookeeper_node_3: 2019-10-21 00:18:44,823 [myid:3] -
INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@222] -
Accepted socket connection from /10.24.8.13:50212
Oct 21 13:18:44 zookeeper_node_3: 2019-10-21 00:18:44,825 [myid:3] -
INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@949] -
Client attempting to establish new session at /10.24.8.13:50212
Oct 21 13:18:44 zookeeper_node_3: 2019-10-21 00:18:44,833 [myid:3] -
INFO [CommitProcessor:3:ZooKeeperServer@694] - Established session
0x30b2dfdd8ac0000 with negotiated timeout 10000 for client /10.24.8.13:50212
Oct 21 13:18:53 zookeeper_node_3: 2019-10-21 00:18:53,374 [myid:3] -
INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@222] -
Accepted socket connection from /10.24.8.13:50314
Oct 21 13:18:53 zookeeper_node_3: 2019-10-21 00:18:53,374 [myid:3] -
INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@949] -
Client attempting to establish new session at /10.24.8.13:50314
Oct 21 13:18:53 zookeeper_node_3: 2019-10-21 00:18:53,385 [myid:3] -
INFO [CommitProcessor:3:ZooKeeperServer@694] - Established session
0x30b2dfdd8ac0001 with negotiated timeout 10000 for client /10.24.8.13:50314
Oct 21 13:18:53 zookeeper_node_3: 2019-10-21 00:18:53,588 [myid:3] -
INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1056] -
Closed socket connection for client /10.24.8.13:50314 which had
sessionid 0x30b2dfdd8ac0001
I also checked the Logs from the update I did on Wednesday night to
update to 3.5.6. This is the Log of the start of zookeeper_node_1 until
the errors show up... Can't see any exceptions :(
Oct 23 02:07:03 zookeeper_node_1: setting ZOO_LOG4J_PROP=INFO,CONSOLE
Oct 23 02:07:03 zookeeper_node_1: ZooKeeper JMX enabled by default
Oct 23 02:07:03 zookeeper_node_1: Using config:
/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../conf/zoo.cfg
Oct 23 02:07:05 zookeeper_node_1: Oct 22, 2019 13:07:05 +0000 [1 1]
com.newrelic INFO: New Relic Agent: Loading configuration file
"/opt/zookeeper-cluster/newrelic/./newrelic.yml"
Oct 23 02:07:05 zookeeper_node_1: Oct 22, 2019 13:07:05 +0000 [1 1]
com.newrelic INFO: Using default collector host: collector.newrelic.com
Oct 23 02:07:05 zookeeper_node_1: Oct 22, 2019 13:07:05 +0000 [1 1]
com.newrelic INFO: New Relic Agent: Writing to log file:
/opt/zookeeper-cluster/newrelic/logs/newrelic_agent.log
Oct 23 02:07:28 zookeeper_node_1: 2019-10-22 13:07:28,743 [myid:] -
INFO [main:QuorumPeerConfig@133] - Reading configuration from:
/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../conf/zoo.cfg
Oct 23 02:07:28 zookeeper_node_1: 2019-10-22 13:07:28,764 [myid:] -
INFO [main:QuorumPeerConfig@385] - clientPortAddress is
0.0.0.0/0.0.0.0:2181
Oct 23 02:07:28 zookeeper_node_1: 2019-10-22 13:07:28,764 [myid:] -
INFO [main:QuorumPeerConfig@389] - secureClientPort is not set
Oct 23 02:07:28 zookeeper_node_1: 2019-10-22 13:07:28,877 [myid:1] -
INFO [main:DatadirCleanupManager@78] - autopurge.snapRetainCount set to 3
Oct 23 02:07:28 zookeeper_node_1: 2019-10-22 13:07:28,878 [myid:1] -
INFO [main:DatadirCleanupManager@79] - autopurge.purgeInterval set to 0
Oct 23 02:07:28 zookeeper_node_1: 2019-10-22 13:07:28,878 [myid:1] -
INFO [main:DatadirCleanupManager@101] - Purge task is not scheduled.
Oct 23 02:07:28 zookeeper_node_1: 2019-10-22 13:07:28,889 [myid:1] -
INFO [main:ManagedUtil@46] - Log4j found with jmx enabled.
Oct 23 02:07:29 zookeeper_node_1: 2019-10-22 13:07:29,046 [myid:1] -
INFO [main:QuorumPeerMain@141] - Starting quorum peer
Oct 23 02:07:29 zookeeper_node_1: 2019-10-22 13:07:29,129 [myid:1] -
INFO [main:ServerCnxnFactory@135] - Using
org.apache.zookeeper.server.NIOServerCnxnFactory as server connection
factory
Oct 23 02:07:29 zookeeper_node_1: 2019-10-22 13:07:29,182 [myid:1] -
INFO [main:NIOServerCnxnFactory@673] - Configuring NIO connection
handler with 10s sessionless connection timeout, 1 selector thread(s), 8
worker threads, and 64 kB direct buffers.
Oct 23 02:07:29 zookeeper_node_1: 2019-10-22 13:07:29,247 [myid:1] -
INFO [main:NIOServerCnxnFactory@686] - binding to port 0.0.0.0/0.0.0.0:2181
Oct 23 02:07:30 zookeeper_node_1: 2019-10-22 13:07:30,160 [myid:1] -
INFO [main:Log@193] - Logging initialized @26647ms to
org.eclipse.jetty.util.log.Slf4jLog
Oct 23 02:07:31 zookeeper_node_1: 2019-10-22 13:07:31,511 [myid:1] -
WARN [main:ContextHandler@1588] -
o.e.j.s.ServletContextHandler@7add323c{/,null,UNAVAILABLE} contextPath
ends with /*
Oct 23 02:07:31 zookeeper_node_1: 2019-10-22 13:07:31,512 [myid:1] -
WARN [main:ContextHandler@1599] - Empty contextPath
Oct 23 02:07:32 zookeeper_node_1: 2019-10-22 13:07:32,381 [myid:1] -
INFO [main:X509Util@79] - Setting -D
jdk.tls.rejectClientInitiatedRenegotiation=true to disable
client-initiated TLS renegotiation
Oct 23 02:07:32 zookeeper_node_1: 2019-10-22 13:07:32,420 [myid:1] -
INFO [main:FileTxnSnapLog@103] - zookeeper.snapshot.trust.empty : false
Oct 23 02:07:34 zookeeper_node_1: 2019-10-22 13:07:34,763 [myid:1] -
INFO [main:QuorumPeer@1488] - Local sessions disabled
Oct 23 02:07:34 zookeeper_node_1: 2019-10-22 13:07:34,763 [myid:1] -
INFO [main:QuorumPeer@1499] - Local session upgrading disabled
Oct 23 02:07:34 zookeeper_node_1: 2019-10-22 13:07:34,764 [myid:1] -
INFO [main:QuorumPeer@1466] - tickTime set to 2000
Oct 23 02:07:34 zookeeper_node_1: 2019-10-22 13:07:34,764 [myid:1] -
INFO [main:QuorumPeer@1510] - minSessionTimeout set to 4000
Oct 23 02:07:34 zookeeper_node_1: 2019-10-22 13:07:34,764 [myid:1] -
INFO [main:QuorumPeer@1521] - maxSessionTimeout set to 40000
Oct 23 02:07:34 zookeeper_node_1: 2019-10-22 13:07:34,764 [myid:1] -
INFO [main:QuorumPeer@1536] - initLimit set to 10
Oct 23 02:07:34 zookeeper_node_1: 2019-10-22 13:07:34,812 [myid:1] -
INFO [main:ZKDatabase@117] - zookeeper.snapshotSizeFactor = 0.33
Oct 23 02:07:34 zookeeper_node_1: 2019-10-22 13:07:34,828 [myid:1] -
INFO [main:QuorumPeer@1781] - Using insecure (non-TLS) quorum communication
Oct 23 02:07:34 zookeeper_node_1: 2019-10-22 13:07:34,828 [myid:1] -
INFO [main:QuorumPeer@1787] - Port unification disabled
Oct 23 02:07:34 zookeeper_node_1: 2019-10-22 13:07:34,828 [myid:1] -
INFO [main:QuorumPeer@2154] - QuorumPeer communication is not secured!
(SASL auth disabled)
Oct 23 02:07:35 zookeeper_node_1: 2019-10-22 13:07:34,828 [myid:1] -
INFO [main:QuorumPeer@2183] - quorum.cnxn.threads.size set to 20
Oct 23 02:07:40 zookeeper_node_1: 2019-10-22 13:07:39,905 [myid:1] -
INFO [main:FileSnap@83] - Reading snapshot
/mnt/zk_data/version-2/snapshot.6c0070e6c8
Oct 23 02:07:43 zookeeper_node_1: 2019-10-22 13:07:43,344 [myid:1] -
INFO [main:Server@370] - jetty-9.4.17.v20190418; built:
2019-04-18T19:45:35.259Z; git: aa1c656c315c011c01e7b21aabb04066635b9f67;
jvm 1.8.0_232-b09
Oct 23 02:07:43 zookeeper_node_1: 2019-10-22 13:07:43,491 [myid:1] -
WARN [NIOWorkerThread-1:NIOServerCnxn@370] - Exception causing close of
session 0x0: ZooKeeperServer not running
Oct 23 02:07:43 zookeeper_node_1: 2019-10-22 13:07:43,520 [myid:1] -
WARN [NIOWorkerThread-2:NIOServerCnxn@370] - Exception causing close of
session 0x0: ZooKeeperServer not running
Oct 23 02:07:43 zookeeper_node_1: 2019-10-22 13:07:43,785 [myid:1] -
INFO [main:DefaultSessionIdManager@365] - DefaultSessionIdManager
workerName=node0
Oct 23 02:07:43 zookeeper_node_1: 2019-10-22 13:07:43,785 [myid:1] -
INFO [main:DefaultSessionIdManager@370] - No SessionScavenger set,
using defaults
Oct 23 02:07:43 zookeeper_node_1: 2019-10-22 13:07:43,789 [myid:1] -
INFO [main:HouseKeeper@149] - node0 Scavenging every 600000ms
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,088 [myid:1] -
INFO [main:ContextHandler@855] - Started
o.e.j.s.ServletContextHandler@7add323c{/,null,AVAILABLE}
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,125 [myid:1] -
INFO [main:AbstractConnector@292] - Started
ServerConnector@5eed2d86{HTTP/1.1,[http/1.1]}{0.0.0.0:8080}
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,126 [myid:1] -
INFO [main:Server@410] - Started @40612ms
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,126 [myid:1] -
INFO [main:JettyAdminServer@112] - Started AdminServer on address
0.0.0.0, port 8080 and command URL /commands
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,154 [myid:1] -
INFO [main:QuorumCnxManager$Listener@861] - Election port bind maximum
retries is 3
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,196 [myid:1] -
INFO [QuorumPeerListener:QuorumCnxManager$Listener@911] - My election
bind port: /0.0.0.0:3888
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,251 [myid:1] -
INFO
[QuorumPeer[myid=1](plain=/0.0.0.0:2181)(secure=disabled):QuorumPeer@1193]
- LOOKING
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,253 [myid:1] -
INFO
[QuorumPeer[myid=1](plain=/0.0.0.0:2181)(secure=disabled):FastLeaderElection@885]
- New election. My id = 1, proposed zxid=0x6c0071173e
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,261 [myid:1] -
INFO [WorkerSender[myid=1]:QuorumCnxManager@432] - Have smaller server
identifier, so dropping the connection: (2, 1)
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,263 [myid:1] -
INFO [WorkerSender[myid=1]:QuorumCnxManager@432] - Have smaller server
identifier, so dropping the connection: (3, 1)
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,264 [myid:1] -
INFO [WorkerReceiver[myid=1]:FastLeaderElection@679] - Notification: 2
(message format version), 1 (n.leader), 0x6c0071173e (n.zxid), 0x1
(n.round), LOOKING (n.state), 1 (n.sid), 0x6c (n.peerEPoch), LOOKING (my
state)0 (n.config version)
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,272 [myid:1] -
INFO [/0.0.0.0:3888:QuorumCnxManager$Listener@918] - Received
connection request 10.24.8.28:43680
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,330 [myid:1] -
INFO [/0.0.0.0:3888:QuorumCnxManager$Listener@918] - Received
connection request 10.24.8.29:53138
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,376 [myid:1] -
INFO
[WorkerReceiver[myid=1]:FastLeaderElection$Messenger$WorkerReceiver@264]
- Backward compatibility mode (36 bits), server id: 2
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,376 [myid:1] -
INFO
[WorkerReceiver[myid=1]:FastLeaderElection$Messenger$WorkerReceiver@309]
- Backward compatibility mode (before reconfig), server id: 2
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,376 [myid:1] -
INFO [WorkerReceiver[myid=1]:FastLeaderElection@679] - Notification: 0
(message format version), 2 (n.leader), 0x6b000007e6 (n.zxid), 0x1f
(n.round), LOOKING (n.state), 2 (n.sid), 0x6b (n.peerEPoch), LOOKING (my
state)
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,378 [myid:1] -
INFO [WorkerReceiver[myid=1]:FastLeaderElection@679] - Notification: 2
(message format version), 1 (n.leader), 0x6c0071173e (n.zxid), 0x1f
(n.round), LOOKING (n.state), 1 (n.sid), 0x6c (n.peerEPoch), LOOKING (my
state)0 (n.config version)
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,379 [myid:1] -
INFO
[WorkerReceiver[myid=1]:FastLeaderElection$Messenger$WorkerReceiver@264]
- Backward compatibility mode (36 bits), server id: 3
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,379 [myid:1] -
INFO
[WorkerReceiver[myid=1]:FastLeaderElection$Messenger$WorkerReceiver@309]
- Backward compatibility mode (before reconfig), server id: 3
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,379 [myid:1] -
INFO [WorkerReceiver[myid=1]:FastLeaderElection@679] - Notification: 0
(message format version), 3 (n.leader), 0x6c001c583d (n.zxid), 0x20
(n.round), LOOKING (n.state), 3 (n.sid), 0x6c (n.peerEPoch), LOOKING (my
state)
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,410 [myid:1] -
WARN [NIOWorkerThread-3:NIOServerCnxn@370] - Exception causing close of
session 0x0: ZooKeeperServer not running
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,427 [myid:1] -
INFO [WorkerReceiver[myid=1]:FastLeaderElection@679] - Notification: 2
(message format version), 1 (n.leader), 0x6c0071173e (n.zxid), 0x20
(n.round), LOOKING (n.state), 1 (n.sid), 0x6c (n.peerEPoch), LOOKING (my
state)0 (n.config version)
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,428 [myid:1] -
INFO
[WorkerReceiver[myid=1]:FastLeaderElection$Messenger$WorkerReceiver@264]
- Backward compatibility mode (36 bits), server id: 2
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,428 [myid:1] -
INFO
[WorkerReceiver[myid=1]:FastLeaderElection$Messenger$WorkerReceiver@309]
- Backward compatibility mode (before reconfig), server id: 2
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,428 [myid:1] -
INFO [WorkerReceiver[myid=1]:FastLeaderElection@679] - Notification: 0
(message format version), 2 (n.leader), 0x6b000007e6 (n.zxid), 0x1f
(n.round), LEADING (n.state), 2 (n.sid), 0x6c (n.peerEPoch), LOOKING (my
state)
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,429 [myid:1] -
INFO
[WorkerReceiver[myid=1]:FastLeaderElection$Messenger$WorkerReceiver@264]
- Backward compatibility mode (36 bits), server id: 3
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,429 [myid:1] -
INFO
[WorkerReceiver[myid=1]:FastLeaderElection$Messenger$WorkerReceiver@309]
- Backward compatibility mode (before reconfig), server id: 3
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,429 [myid:1] -
INFO [WorkerReceiver[myid=1]:FastLeaderElection@679] - Notification: 0
(message format version), 2 (n.leader), 0x6b000007e6 (n.zxid), 0x1f
(n.round), FOLLOWING (n.state), 3 (n.sid), 0x6c (n.peerEPoch), LOOKING
(my state)
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,429 [myid:1] -
INFO
[WorkerReceiver[myid=1]:FastLeaderElection$Messenger$WorkerReceiver@264]
- Backward compatibility mode (36 bits), server id: 3
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,430 [myid:1] -
INFO
[WorkerReceiver[myid=1]:FastLeaderElection$Messenger$WorkerReceiver@309]
- Backward compatibility mode (before reconfig), server id: 3
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,430 [myid:1] -
INFO [WorkerReceiver[myid=1]:FastLeaderElection@679] - Notification: 0
(message format version), 2 (n.leader), 0x6b000007e6 (n.zxid), 0x1f
(n.round), FOLLOWING (n.state), 3 (n.sid), 0x6c (n.peerEPoch), LOOKING
(my state)
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,430 [myid:1] -
INFO
[QuorumPeer[myid=1](plain=/0.0.0.0:2181)(secure=disabled):QuorumPeer@1269]
- FOLLOWING
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,462 [myid:1] -
INFO
[QuorumPeer[myid=1](plain=/0.0.0.0:2181)(secure=disabled):Learner@91] -
TCP NoDelay set to: true
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,488 [myid:1] -
INFO
[QuorumPeer[myid=1](plain=/0.0.0.0:2181)(secure=disabled):Environment@109]
- Server
environment:zookeeper.version=3.5.6-c11b7e26bc554b8523dc929761dd28808913f091,
built on 10/08/2019 20:18 GMT
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,490 [myid:1] -
INFO
[QuorumPeer[myid=1](plain=/0.0.0.0:2181)(secure=disabled):Environment@109]
- Server environment:host.name=zookeeper_node_1
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,490 [myid:1] -
INFO
[QuorumPeer[myid=1](plain=/0.0.0.0:2181)(secure=disabled):Environment@109]
- Server environment:java.version=1.8.0_232
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,491 [myid:1] -
INFO
[QuorumPeer[myid=1](plain=/0.0.0.0:2181)(secure=disabled):Environment@109]
- Server environment:java.vendor=Oracle Corporation
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,491 [myid:1] -
INFO
[QuorumPeer[myid=1](plain=/0.0.0.0:2181)(secure=disabled):Environment@109]
- Server environment:java.home=/usr/local/openjdk-8
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,491 [myid:1] -
INFO
[QuorumPeer[myid=1](plain=/0.0.0.0:2181)(secure=disabled):Environment@109]
- Server
environment:java.class.path=/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../zookeeper-server/target/classes:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../build/classes:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../zookeeper-server/target/lib/*.jar:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../build/lib/*.jar:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../lib/zookeeper-jute-3.5.6.jar:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../lib/zookeeper-3.5.6.jar:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../lib/slf4j-log4j12-1.7.25.jar:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../lib/slf4j-api-1.7.25.jar:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../lib/netty-transport-native-unix-common-4.1.42.Final.jar:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../lib/netty-transport-native-epoll-4.1.42.Final.jar:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../lib/netty-transport-4.1.42.Final.jar:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../lib/netty-resolver-4.1.42.Final.jar:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../lib/netty-handler-4.1.42.Final.jar:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../lib/netty-common-4.1.42.Final.jar:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../lib/netty-codec-4.1.42.Final.jar:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../lib/netty-buffer-4.1.42.Final.jar:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../lib/log4j-1.2.17.jar:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../lib/json-simple-1.1.1.jar:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../lib/jline-2.11.jar:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../lib/jetty-util-9.4.17.v20190418.jar:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../lib/jetty-servlet-9.4.17.v20190418.jar:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../lib/jetty-server-9.4.17.v20190418.jar:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../lib/jetty-security-9.4.17.v20190418.jar:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../lib/jetty-io-9.4.17.v20190418.jar:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../lib/jetty-http-9.4.17.v20190418.jar:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../lib/javax.servlet-api-3.1.0.jar:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../lib/jackson-databind-2.9.10.jar:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../lib/jackson-core-2.9.10.jar:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../lib/jackson-annotations-2.9.10.jar:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../lib/commons-cli-1.2.jar:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../lib/audience-annotations-0.5.0.jar:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../zookeeper-*.jar:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../zookeeper-server/src/main/resources/lib/*.jar:/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../conf::/opt/zookeeper-cluster/newrelic/newrelic.jar
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,491 [myid:1] -
INFO
[QuorumPeer[myid=1](plain=/0.0.0.0:2181)(secure=disabled):Environment@109]
- Server
environment:java.library.path=/usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,491 [myid:1] -
INFO
[QuorumPeer[myid=1](plain=/0.0.0.0:2181)(secure=disabled):Environment@109]
- Server environment:java.io.tmpdir=/tmp
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,491 [myid:1] -
INFO
[QuorumPeer[myid=1](plain=/0.0.0.0:2181)(secure=disabled):Environment@109]
- Server environment:java.compiler=<NA>
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,491 [myid:1] -
INFO
[QuorumPeer[myid=1](plain=/0.0.0.0:2181)(secure=disabled):Environment@109]
- Server environment:os.name=Linux
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,491 [myid:1] -
INFO
[QuorumPeer[myid=1](plain=/0.0.0.0:2181)(secure=disabled):Environment@109]
- Server environment:os.arch=amd64
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,492 [myid:1] -
INFO
[QuorumPeer[myid=1](plain=/0.0.0.0:2181)(secure=disabled):Environment@109]
- Server environment:os.version=3.10.0-862.2.3.el7.x86_64
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,492 [myid:1] -
INFO
[QuorumPeer[myid=1](plain=/0.0.0.0:2181)(secure=disabled):Environment@109]
- Server environment:user.name=root
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,492 [myid:1] -
INFO
[QuorumPeer[myid=1](plain=/0.0.0.0:2181)(secure=disabled):Environment@109]
- Server environment:user.home=/root
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,492 [myid:1] -
INFO
[QuorumPeer[myid=1](plain=/0.0.0.0:2181)(secure=disabled):Environment@109]
- Server environment:user.dir=/
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,492 [myid:1] -
INFO
[QuorumPeer[myid=1](plain=/0.0.0.0:2181)(secure=disabled):Environment@109]
- Server environment:os.memory.free=241MB
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,492 [myid:1] -
INFO
[QuorumPeer[myid=1](plain=/0.0.0.0:2181)(secure=disabled):Environment@109]
- Server environment:os.memory.max=889MB
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,492 [myid:1] -
INFO
[QuorumPeer[myid=1](plain=/0.0.0.0:2181)(secure=disabled):Environment@109]
- Server environment:os.memory.total=516MB
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,495 [myid:1] -
INFO
[QuorumPeer[myid=1](plain=/0.0.0.0:2181)(secure=disabled):ZooKeeperServer@938]
- minSessionTimeout set to 4000
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,495 [myid:1] -
INFO
[QuorumPeer[myid=1](plain=/0.0.0.0:2181)(secure=disabled):ZooKeeperServer@947]
- maxSessionTimeout set to 40000
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,496 [myid:1] -
INFO
[QuorumPeer[myid=1](plain=/0.0.0.0:2181)(secure=disabled):ZooKeeperServer@166]
- Created server with tickTime 2000 minSessionTimeout 4000
maxSessionTimeout 40000 datadir /mnt/zk_data_log/version-2 snapdir
/mnt/zk_data/version-2
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,496 [myid:1] -
INFO
[QuorumPeer[myid=1](plain=/0.0.0.0:2181)(secure=disabled):Follower@69] -
FOLLOWING - LEADER ELECTION TOOK - 66 MS
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,514 [myid:1] -
INFO
[QuorumPeer[myid=1](plain=/0.0.0.0:2181)(secure=disabled):Learner@391] -
Getting a diff from the leader 0x6c007117dd
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,523 [myid:1] -
WARN
[QuorumPeer[myid=1](plain=/0.0.0.0:2181)(secure=disabled):Learner@454] -
Got zxid 0x6c0071173f expected 0x1
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,546 [myid:1] -
INFO
[QuorumPeer[myid=1](plain=/0.0.0.0:2181)(secure=disabled):Learner@546] -
Learner received NEWLEADER message
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,669 [myid:1] -
WARN [NIOWorkerThread-4:NIOServerCnxn@370] - Exception causing close of
session 0x0: ZooKeeperServer not running
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,811 [myid:1] -
INFO
[QuorumPeer[myid=1](plain=/0.0.0.0:2181)(secure=disabled):Learner@529] -
Learner received UPTODATE message
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,822 [myid:1] -
INFO
[QuorumPeer[myid=1](plain=/0.0.0.0:2181)(secure=disabled):CommitProcessor@256]
- Configuring CommitProcessor with 4 worker threads.
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,854 [myid:1] -
WARN
[QuorumPeer[myid=1](plain=/0.0.0.0:2181)(secure=disabled):Follower@125]
- Got zxid 0x6c007117de expected 0x1
Oct 23 02:07:44 zookeeper_node_1: 2019-10-22 13:07:44,859 [myid:1] -
INFO [SyncThread:1:FileTxnLog@216] - Creating new log file: log.6c0071173f
Oct 23 02:07:45 zookeeper_node_1: 2019-10-22 13:07:45,345 [myid:1] -
WARN [NIOWorkerThread-5:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 23 02:07:46 zookeeper_node_1: 2019-10-22 13:07:45,942 [myid:1] -
WARN [NIOWorkerThread-6:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 23 02:07:46 zookeeper_node_1: 2019-10-22 13:07:46,474 [myid:1] -
WARN [NIOWorkerThread-7:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 23 02:07:47 zookeeper_node_1: 2019-10-22 13:07:47,111 [myid:1] -
WARN [NIOWorkerThread-8:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 23 02:07:47 zookeeper_node_1: 2019-10-22 13:07:47,292 [myid:1] -
WARN [NIOWorkerThread-1:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Thanks
Sebastian
On 25-Oct-19 11:17 AM, Enrico Olivelli wrote:
Sebastian
This 'null' looks like a NullPointerException (this kind f exceptions
tracks only the full stacktrace at the first occurrence usually)
Can you find some full stacktrace of the error?
Are you able to enable more detailed logging?
Do you see errors on the client (kafka broker?) ? Maybe on
oeg.apache.zookeeper.xxx logs
Enrico
Il ven 25 ott 2019, 00:05 Sebastian Schmitz <
[email protected]> ha scritto:
Hello,
I did a rolling upgrade of the Zookeeper from 3.4.14 to 3.5.6 on 23rd in
my Test-Environment. It's zookeeping a three node Kafka-Cluster running
on 2.3.0.
After the update I get spammed with these warnings:
Oct 25 10:56:23 zookeeper_node_1: 2019-10-24 21:56:23,119 [myid:1] -
WARN [NIOWorkerThread-6:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 25 10:56:23 zookeeper_node_2: 2019-10-24 21:56:23,478 [myid:2] -
WARN [NIOWorkerThread-1:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 25 10:56:23 zookeeper_node_3: 2019-10-24 21:56:23,531 [myid:3] -
WARN [NIOWorkerThread-3:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 25 10:56:23 zookeeper_node_1: 2019-10-24 21:56:23,776 [myid:1] -
WARN [NIOWorkerThread-8:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 25 10:56:23 zookeeper_node_2: 2019-10-24 21:56:23,879 [myid:2] -
WARN [NIOWorkerThread-5:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 25 10:56:24 zookeeper_node_3: 2019-10-24 21:56:24,086 [myid:3] -
WARN [NIOWorkerThread-4:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 25 10:56:24 zookeeper_node_1: 2019-10-24 21:56:24,090 [myid:1] -
WARN [NIOWorkerThread-4:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 25 10:56:24 zookeeper_node_2: 2019-10-24 21:56:24,497 [myid:2] -
WARN [NIOWorkerThread-2:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 25 10:56:24 zookeeper_node_3: 2019-10-24 21:56:24,601 [myid:3] -
WARN [NIOWorkerThread-1:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 25 10:56:24 zookeeper_node_1: 2019-10-24 21:56:24,798 [myid:1] -
WARN [NIOWorkerThread-3:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 25 10:56:24 zookeeper_node_3: 2019-10-24 21:56:24,904 [myid:3] -
WARN [NIOWorkerThread-6:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 25 10:56:25 zookeeper_node_2: 2019-10-24 21:56:25,007 [myid:2] -
WARN [NIOWorkerThread-3:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 25 10:56:25 zookeeper_node_1: 2019-10-24 21:56:25,260 [myid:1] -
WARN [NIOWorkerThread-5:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 25 10:56:25 zookeeper_node_3: 2019-10-24 21:56:25,467 [myid:3] -
WARN [NIOWorkerThread-8:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 25 10:56:25 zookeeper_node_2: 2019-10-24 21:56:25,619 [myid:2] -
WARN [NIOWorkerThread-8:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 25 10:56:25 zookeeper_node_1: 2019-10-24 21:56:25,666 [myid:1] -
WARN [NIOWorkerThread-7:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 25 10:56:26 zookeeper_node_3: 2019-10-24 21:56:25,923 [myid:3] -
WARN [NIOWorkerThread-5:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 25 10:56:26 zookeeper_node_2: 2019-10-24 21:56:26,178 [myid:2] -
WARN [NIOWorkerThread-5:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 25 10:56:26 zookeeper_node_1: 2019-10-24 21:56:26,329 [myid:1] -
WARN [NIOWorkerThread-1:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 25 10:56:26 zookeeper_node_3: 2019-10-24 21:56:26,484 [myid:3] -
WARN [NIOWorkerThread-3:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 25 10:56:26 zookeeper_node_2: 2019-10-24 21:56:26,792 [myid:2] -
WARN [NIOWorkerThread-4:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 25 10:56:26 zookeeper_node_3: 2019-10-24 21:56:26,890 [myid:3] -
WARN [NIOWorkerThread-7:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 25 10:56:26 zookeeper_node_1: 2019-10-24 21:56:26,888 [myid:1] -
WARN [NIOWorkerThread-2:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 25 10:56:27 zookeeper_node_2: 2019-10-24 21:56:27,347 [myid:2] -
WARN [NIOWorkerThread-7:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 25 10:56:27 zookeeper_node_1: 2019-10-24 21:56:27,354 [myid:1] -
WARN [NIOWorkerThread-4:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 25 10:56:27 zookeeper_node_3: 2019-10-24 21:56:27,662 [myid:3] -
WARN [NIOWorkerThread-2:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 25 10:56:27 zookeeper_node_3: 2019-10-24 21:56:27,810 [myid:3] -
WARN [NIOWorkerThread-6:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 25 10:56:27 zookeeper_node_1: 2019-10-24 21:56:27,811 [myid:1] -
WARN [NIOWorkerThread-2:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 25 10:56:27 zookeeper_node_2: 2019-10-24 21:56:27,816 [myid:2] -
WARN [NIOWorkerThread-2:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 25 10:56:28 zookeeper_node_2: 2019-10-24 21:56:28,366 [myid:2] -
WARN [NIOWorkerThread-6:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
Oct 25 10:56:28 zookeeper_node_1: 2019-10-24 21:56:28,474 [myid:1] -
WARN [NIOWorkerThread-6:NIOServerCnxn@370] - Exception causing close of
session 0x0: null
A quick search didn't return anything, but my guess is that it might
have to do with the upgrade from 3.4.14 and maybe old stuff remaining?
So any idea for what to check or do would be greatly appreciated.
Thanks
Sebastian
--
DISCLAIMER
This email contains information that is confidential and which
may be
legally privileged. If you have received this email in error please
notify the sender immediately and delete the email.
This email is intended
solely for the use of the intended recipient and you may not use or
disclose this email in any way.
--
DISCLAIMER
This email contains information that is confidential and which
may be
legally privileged. If you have received this email in error please
notify the sender immediately and delete the email.
This email is intended
solely for the use of the intended recipient and you may not use or
disclose this email in any way.
