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 Mon, 28 Oct 2019 23:51:53 GMT
Hello again,

just as a final update on this..... We had a weird consumer which 
someone updated without informing me... Turning it off also turned off 
the errors from spamming the logs.

However it seems like the 3.5.6 is less informative than the 3.4.14 we 
had before as 3.4.14 also had the IP-Address when the connection was 
opened in the messages and not just the warnings...

Best regards

Sebastian


On 25-Oct-19 1:26 PM, Sebastian Schmitz wrote:
> 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