You are viewing a plain text version of this content. The canonical link for it is here.

Posted to user@zookeeper.apache.org by Sebastian Schmitz <se...@propellerhead.co.nz> on 2019/10/24 22:05:38 UTC

Zookeeper 3.5.6 - Exception causing close of session 0x0: null

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.

Re: Zookeeper 3.5.6 - Exception causing close of session 0x0: null

Posted by Sebastian Schmitz <se...@propellerhead.co.nz>.

Hello Enrico,

yes, a custom made client, that was updated and now is stopped again...

The difference is that in new version only this is the output:

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

In the 3.4.14 it was also stating where the connection came from before 
giving the warning:

Oct 21 16:02:16 zookeeper_node_2: 2019-10-2103:02:16,679 [myid:2] - INFO 
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@222] - 
Accepted socket connection from /10.24.8.13:60517

Best regards

Sebastian


On 29-Oct-19 7:06 PM, Enrico Olivelli wrote:
> 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.
>>
>>

-- 
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.

Re: Zookeeper 3.5.6 - Exception causing close of session 0x0: null

Posted by Enrico Olivelli <eo...@gmail.com>.

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.
>
>

Re: Zookeeper 3.5.6 - Exception causing close of session 0x0: null

Posted by Sebastian Schmitz <se...@propellerhead.co.nz>.

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.

Re: Zookeeper 3.5.6 - Exception causing close of session 0x0: null

Posted by Sebastian Schmitz <se...@propellerhead.co.nz>.

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.

Re: Zookeeper 3.5.6 - Exception causing close of session 0x0: null

Posted by Enrico Olivelli <eo...@gmail.com>.

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.
>

Re: Zookeeper 3.5.6 - Exception causing close of session 0x0: null

Posted by Sebastian Schmitz <se...@propellerhead.co.nz>.

Hello Again,

I have a small correction to make... It didn't start after the upgrade 
to 3.5.6, but just in the middle of a day at 14:50 on 21st.... And the 
upgrade to 3.5.6 didn't automagically solve it....

So any help to find the cause of this would be great.

Thanks

Sebastian


On 25-Oct-19 11:05 AM, Sebastian Schmitz wrote:
> 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.