Zookeeper connection issue on historical node.

[Lu Xuechao]

Hi Team,

We found tons of exception logs thrown out on one of our druid historical node about zookeeper connection. we've found this issues days back, but after we restarted the problematic host, it now happened again. While the other historical node has no such issue with the same configurations.

The exceptions are like below:

2014-11-02 19:44:44,607 INFO  [ServerInventoryView-0-EventThread] org.apache.curator.framework.state.ConnectionStateManager - State change: SUSPENDED
2014-11-02 19:44:44,607 WARN  [ServerInventoryView-0-EventThread] org.apache.curator.framework.state.ConnectionStateManager - ConnectionStateManager queue full - dropping events to make room
2014-11-02 19:44:44,607 ERROR [ServerInventoryView-0-EventThread] org.apache.curator.framework.imps.CuratorFrameworkImpl - Background operation retry gave up
org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode = ConnectionLoss
    at org.apache.zookeeper.KeeperException.create(KeeperException.java:99)
    at org.apache.curator.framework.imps.CuratorFrameworkImpl.checkBackgroundRetry(CuratorFrameworkImpl.java:695)
    at org.apache.curator.framework.imps.CuratorFrameworkImpl.processBackgroundOperation(CuratorFrameworkImpl.java:496)
    at org.apache.curator.framework.imps.GetChildrenBuilderImpl$2.processResult(GetChildrenBuilderImpl.java:166)
    at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:593)
    at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:498)
2014-11-02 19:44:44,607 ERROR [ServerInventoryView-0-EventThread] org.apache.curator.framework.imps.CuratorFrameworkImpl - Background operation retry gave up
org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode = ConnectionLoss
    at org.apache.zookeeper.KeeperException.create(KeeperException.java:99)
    at org.apache.curator.framework.imps.CuratorFrameworkImpl.checkBackgroundRetry(CuratorFrameworkImpl.java:695)
    at org.apache.curator.framework.imps.CuratorFrameworkImpl.processBackgroundOperation(CuratorFrameworkImpl.java:496)
    at org.apache.curator.framework.imps.GetChildrenBuilderImpl$2.processResult(GetChildrenBuilderImpl.java:166)
    at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:593)
    at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:498)
2014-11-02 19:44:44,607 ERROR [ServerInventoryView-0-EventThread] org.apache.curator.framework.imps.CuratorFrameworkImpl - Background operation retry gave up
org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode = ConnectionLoss
    at org.apache.zookeeper.KeeperException.create(KeeperException.java:99)
    at org.apache.curator.framework.imps.CuratorFrameworkImpl.checkBackgroundRetry(CuratorFrameworkImpl.java:695)
    at org.apache.curator.framework.imps.CuratorFrameworkImpl.processBackgroundOperation(CuratorFrameworkImpl.java:496)
    at org.apache.curator.framework.imps.GetChildrenBuilderImpl$2.processResult(GetChildrenBuilderImpl.java:166)
    at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:593)
    at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:498)
2014-11-02 19:44:44,607 ERROR [ServerInventoryView-0-EventThread] org.apache.curator.framework.imps.CuratorFrameworkImpl - Background operation retry gave up
org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode = ConnectionLoss
    at org.apache.zookeeper.KeeperException.create(KeeperException.java:99)
    at org.apache.curator.framework.imps.CuratorFrameworkImpl.checkBackgroundRetry(CuratorFrameworkImpl.java:695)
    at org.apache.curator.framework.imps.CuratorFrameworkImpl.processBackgroundOperation(CuratorFrameworkImpl.java:496)
    at org.apache.curator.framework.imps.GetChildrenBuilderImpl$2.processResult(GetChildrenBuilderImpl.java:166)
    at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:593)
    at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:498)
2014-11-02 19:44:44,607 INFO  [ServerInventoryView-0-EventThread] org.apache.curator.framework.state.ConnectionStateManager - State change: LOST
2014-11-02 19:44:44,607 WARN  [ServerInventoryView-0-EventThread] org.apache.curator.framework.state.ConnectionStateManager - ConnectionStateManager queue full - dropping events to make room
2014-11-02 19:44:44,607 ERROR [ServerInventoryView-0-EventThread] org.apache.curator.framework.imps.CuratorFrameworkImpl - Background operation retry gave up
org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode = ConnectionLoss
    at org.apache.zookeeper.KeeperException.create(KeeperException.java:99)
    at org.apache.curator.framework.imps.CuratorFrameworkImpl.checkBackgroundRetry(CuratorFrameworkImpl.java:695)
    at org.apache.curator.framework.imps.CuratorFrameworkImpl.processBackgroundOperation(CuratorFrameworkImpl.java:496)
    at org.apache.curator.framework.imps.BackgroundSyncImpl$1.processResult(BackgroundSyncImpl.java:50)
    at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:609)
    at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:498)
2014-11-02 19:44:44,607 ERROR [ServerInventoryView-0-EventThread] org.apache.curator.framework.imps.CuratorFrameworkImpl - Background operation retry gave up
org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode = ConnectionLoss
    at org.apache.zookeeper.KeeperException.create(KeeperException.java:99)
    at org.apache.curator.framework.imps.CuratorFrameworkImpl.checkBackgroundRetry(CuratorFrameworkImpl.java:695)
    at org.apache.curator.framework.imps.CuratorFrameworkImpl.processBackgroundOperation(CuratorFrameworkImpl.java:496)
    at org.apache.curator.framework.imps.GetChildrenBuilderImpl$2.processResult(GetChildrenBuilderImpl.java:166)
    at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:593)
    at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:498)



the zookeeper version we are running is 3.4.6. Is this a druid issue or a zookeeper/curator one?

I found these exceptions similar to https://groups.google.com/forum/#!topic/druid-development/BtOyYgwcDjQ but not exact the same and I could not find 'reinstating' information in the log files for the past 12+ hours.

Could you please help? zipped log file attached.

thanks,
xulu

[Fangjin Yang]

Hi Xuechao,

I believe you are probably hitting https://github.com/metamx/druid/issues/783.

This is currently being tracked with an Apache curator issue. What version of Druid is this? We'd like to be able to provide a stack trace with 2.6.0 version of Curator (which is what the latest Druid versions use) to the Curator guys.

[Lu Xuechao]

I am using 0.6.146.

[Fangjin Yang]

It is odd that only one historical node is disconnecting from ZK, usually if there are ZK issues, all nodes are affected. If you replace the node, does the problem persist elsewhere?

[Lu Xuechao]

Hi Fangjin,

This occurred again today. Now we have this issue on all of our broker nodes.

the error log on druid side:
2014-11-12 02:24:32,869 INFO  [main-SendThread(phx7b02c-f8c8.stratus.phx.ebay.com:2181)] org.apache.zookeeper.ClientCnxn - Client session timed out, have not heard from server in 39682ms for sessionid 0x346f6139ca629a9, closing socket connection and attempting reconnect

2014-11-12 02:24:35,472 INFO  [main-SendThread(chd1b02c-4f09.stratus.phx.ebay.com:2181)] org.apache.zookeeper.ClientCnxn - Opening socket connection to server chd1b02c-4f09.stratus.phx.ebay.com/10.98.77.143:2181. Will not attempt to authenticate using SASL (unknown error)
2014-11-12 02:24:35,473 INFO  [main-SendThread(chd1b02c-4f09.stratus.phx.ebay.com:2181)] org.apache.zookeeper.ClientCnxn - Socket connection established to chd1b02c-4f09.stratus.phx.ebay.com/10.98.77.143:2181, initiating session
2014-11-12 02:24:35,484 INFO  [main-SendThread(chd1b02c-4f09.stratus.phx.ebay.com:2181)] org.apache.zookeeper.ClientCnxn - Session establishment complete on server chd1b02c-4f09.stratus.phx.ebay.com/10.98.77.143:2181, sessionid = 0x346f6139ca629a9, negotiated timeout = 40000
2014-11-12 02:24:35,502 INFO  [main-EventThread] org.apache.curator.framework.state.ConnectionStateManager - State change: RECONNECTED
2014-11-12 02:24:35,551 INFO  [main-SendThread(chd1b02c-4f09.stratus.phx.ebay.com:2181)] org.apache.zookeeper.ClientCnxn - Unable to read additional data from server sessionid 0x346f6139ca629a9, likely server has closed socket, closing socket connection and attempting reconnect
2014-11-12 02:24:35,669 INFO  [main-EventThread] org.apache.curator.framework.state.ConnectionStateManager - State change: SUSPENDED

corresponding log on zookeeper side:
2014-11-12 02:24:35,481 [myid:1] - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@861] - Client attempting to renew session 0x346f6139ca629
a9 at /10.43.106.69:49630
2014-11-12 02:24:35,482 [myid:1] - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:Learner@108] - Revalidating client: 0x346f6139ca629a9
2014-11-12 02:24:35,483 [myid:1] - INFO  [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:ZooKeeperServer@617] - Established session 0x346f6139ca629a9 with negotiate
d timeout 40000 for client /10.43.106.69:49630
2014-11-12 02:24:35,550 [myid:1] - WARN  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@362] - Exception causing close of session 0x346f6139ca629a9
 due to java.io.IOException: Len error 7589578
2014-11-12 02:24:35,550 [myid:1] - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1007] - Closed socket connection for client /10.43.106.69:4
9630 which had sessionid 0x346f6139ca629a9

So it seems that the "Len error 7589578" is the cause of infinite reconnect tries on druid side.  what can I do to further locate the root cause? I think this is more likely a druid issue.

[Fangjin Yang]

Hi Xuechao, I'm not entirely sure what is causing things and need to dig a bit further.

Looking online, it seems the Kafka folks have hit the same problem: http://mail-archives.apache.org/mod_mbox/zookeeper-user/201108.mbox/%3CCALF7aMQGWHF_r2934HCoNUY...@mail.gmail.com%3E

What version of ZK are you running?

[Fangjin Yang]

Actually, what is your jute.maxBuffer set to? If it is not set on your ZK, can you try setting it to something such as -Djute.maxbuffer=16777216

On Thursday, November 13, 2014 8:18:32 AM UTC-8, Fangjin Yang wrote:

Hi Xuechao, I'm not entirely sure what is causing things and need to dig a bit further.

Looking online, it seems the Kafka folks have hit the same problem: http://mail-archives.apache.org/mod_mbox/zookeeper-user/201108.mbox/%3CCALF7aMQGWHF_r2934HCoNUYhnvqSKymkDEOMwiiVBZLnez...@mail.gmail.com%3E

[Lu Xuechao]

Hi Fangjin,

we are using zookeeper 3.4.6. The maxbuffer in use is in its value 1048575.  I can change this value, but I want to know what is druid trying to save in such a big size 7589578 and under what situation will druid sent such data. Now we are seeing this issues every 3~5 days. After restarting druid broker it disappears for several days and happens again.

thanks.

[Fangjin Yang]

Are you guys using single segment announcing or batch segment announcing? Also, are you guys turning curator compression on?

--
You received this message because you are subscribed to the Google Groups "Druid Development" group.
To unsubscribe from this group and stop receiving emails from it, send an email to druid-developm...@googlegroups.com.
To post to this group, send email to druid-de...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/druid-development/a8d676cd-4cf3-430d-9c21-146039535708%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

[Lu Xuechao]

we don't set druid.curator.compress so it should be false.  How can I know which announcing mode I am using? I can see both BatchDataSegmentAnnouncer  and SingleDataSegmentAnnouncer  in real-time node's log.

2014-11-13 17:20:30,460 INFO  [chief-pulsar_session] io.druid.server.coordination.BatchDataSegmentAnnouncer - Announcing segment[pulsar_session_2014-11-13T17:00:00.000-07:00_2014-11-13T18:00:00.000-07:00_2014-11-13T17:00:00.000-07:00_1] at path[/druid/segments/phxdbx1180.phx.ebay.com:8083/2014-11-13T04:49:13.765-07:000]

2014-11-13 17:59:36,318 INFO  [chief-pulsar_event] io.druid.server.coordination.SingleDataSegmentAnnouncer - Announcing segment[pulsar_event_2014-11-13T18:00
:00.000-07:00_2014-11-13T19:00:00.000-07:00_2014-11-13T18:00:00.000-07:00_1] to path[/druid/servedSegments/phxdbx1180.phx.ebay.com:8083/pulsar_event_2014-11-
13T18:00:00.000-07:00_2014-11-13T19:00:00.000-07:00_2014-11-13T18:00:00.000-07:00_1]

[Fangjin Yang]

You are using legacy segment announcing, so I suspect the large ZK nodes are segment objects. For an idea of what configuration we use in production, see: http://druid.io/docs/latest/Production-Cluster-Configuration.html

I think you can increase jute.maxBuffer and migrate to using compressed & batch announcements.

--
You received this message because you are subscribed to the Google Groups "Druid Development" group.
To unsubscribe from this group and stop receiving emails from it, send an email to druid-developm...@googlegroups.com.
To post to this group, send email to druid-de...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/druid-development/e5a47a85-b19a-4826-ae84-712a95ac3fc8%40googlegroups.com.

[Fangjin Yang]

The original details for migration to use compresed/batch announcements is here:

https://groups.google.com/forum/#!searchin/druid-development/batch$20zk$200.5/druid-development/vKV8pTAd0Gg/VgC8ee6XWZ0J

[Jakub Liska]

Guys I'm having this issue too on Druid 0.9.2 : 

2017-06-19T09:17:53,471 WARN [main-SendThread(172.31.36.2:2181)] org.apache.zookeeper.ClientCnxn - Client session timed out, have not heard from server in 32864ms for sessionid 0x15cbf1ef129000b

2017-06-19T09:17:53,471 INFO [main-SendThread(172.31.36.2:2181)] org.apache.zookeeper.ClientCnxn - Client session timed out, have not heard from server in 32864ms for sessionid 0x15cbf1ef129000b, closing socket connection and attempting reconnect

2017-06-19T09:17:53,572 INFO [main-EventThread] org.apache.curator.framework.state.ConnectionStateManager - State change: SUSPENDED

2017-06-19T09:17:53,574 INFO [ZkCoordinator-0] io.druid.server.coordination.ZkCoordinator - Ignoring event[PathChildrenCacheEvent{type=CONNECTION_SUSPENDED, data=null}]

In my case it happens after a bigger (longer time period) query. 

Any idea how to fix this in 0.9.2 ?

[Nishant Bangarwa]

As you mentioned that only happens after a bigger query, I suspect it could be possible that the ZK disconnect is caused due to long GC pause. 

Can you check your GC pause times and tune JVM settings accordingly ? 

--

You received this message because you are subscribed to the Google Groups "Druid Development" group.
To unsubscribe from this group and stop receiving emails from it, send an email to druid-developm...@googlegroups.com.
To post to this group, send email to druid-de...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/druid-development/34de2f42-5a9a-4e31-941e-8fda03ac816f%40googlegroups.com.

[Jakub Liska]

Yeah this was my first guess, I moved the historical nodes to instances with more memory, so I'll see soon.