zookeeper-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Sebastian Schmitz <sebastian.schm...@propellerhead.co.nz>
Subject Re: Zookeeper 3.5.6 - Exception causing close of session 0x0: null
Date Fri, 25 Oct 2019 00:26:35 GMT
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 <
> sebastian.schmitz@propellerhead.co.nz> 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. 

Mime
View raw message