zookeeper-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Enrico Olivelli <eolive...@gmail.com>
Subject Re: Zookeeper 3.5.6 - Exception causing close of session 0x0: null
Date Tue, 29 Oct 2019 06:06:11 GMT
Il mar 29 ott 2019, 00:52 Sebastian Schmitz <
sebastian.schmitz@propellerhead.co.nz> ha scritto:

> Hello again,
>
> just as a final update on this..... We had a weird consumer which
> someone updated without informing me...


Can you please define 'weird'? A custom made client?



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...
>
If you can point to the differences we can bring back precious logs

Great to see you found the problem

Enrico

>
> 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
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message