https://pinot.apache.org/ logo
Join Slack
Powered by
Hey :wave: , I am facing an issue where after som...
# troubleshooting
k
Hey 👋 , I am facing an issue where after some time (usually a few mins) servers start dying and segments go BAD. These servers are able to join back on restarting, but are DEAD again. In the controller logs I see some errors like:
Copy code
Caught 'java.net.SocketTimeoutException: Read timed out' while executing GET on URL: <http://analytics-pinot-server-0.analytics-pinot-server.email-pinot.svc.test01.k8s.run:8097/table/pinots_REALTIME/size>
Connection error
java.util.concurrent.ExecutionException: java.net.SocketTimeoutException: Read timed out
        at java.util.concurrent.FutureTask.report(FutureTask.java:122) ~[?:?]
        at java.util.concurrent.FutureTask.get(FutureTask.java:191) ~[?:?]
        at org.apache.pinot.controller.util.CompletionServiceHelper.doMultiGetRequest(CompletionServiceHelper.java:79) ~[pinot-all-0.10.0-SNAPSHOT-jar-with-dependencies.jar:0.10.0-SNAPSHOT-8bbf93aa4377dbdf597e7940670893330452b33f]
        at org.apache.pinot.controller.api.resources.ServerTableSizeReader.getSegmentSizeInfoFromServers(ServerTableSizeReader.java:69) ~[pinot-all-0.10.0-SNAPSHOT-jar-with-dependencies.jar:0.10.0-SNAPSHOT-8bbf93aa4377dbdf597e7940670893330452b33f]
        at org.apache.pinot.controller.util.TableSizeReader.getTableSubtypeSize(TableSizeReader.java:181) ~[pinot-all-0.10.0-SNAPSHOT-jar-with-dependencies.jar:0.10.0-SNAPSHOT-8bbf93aa4377dbdf597e7940670893330452b33f]
        at org.apache.pinot.controller.util.TableSizeReader.getTableSizeDetails(TableSizeReader.java:101) ~[pinot-all-0.10.0-SNAPSHOT-jar-with-dependencies.jar:0.10.0-SNAPSHOT-8bbf93aa4377dbdf597e7940670893330452b33f]
        at org.apache.pinot.controller.api.resources.TableSize.getTableSize(TableSize.java:83) ~[pinot-all-0.10.0-SNAPSHOT-jar-with-dependencies.jar:0.10.0-SNAPSHOT-8bbf93aa4377dbdf597e7940670893330452b33f]
        at jdk.internal.reflect.GeneratedMethodAccessor818.invoke(Unknown Source) ~[?:?]
        at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
        at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory.lambda$static$0(ResourceMethodInvocationHandlerFactory.java:52) ~[pinot-all-0.10.0-SNAPSHOT-jar-with-dependencies.jar:0.10.0-SNAPSHOT-8bbf93aa4377dbdf597e7940670893330452b33f]
        at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:124) [pinot-all-0.10.0-SNAPSHOT-jar-with-dependencies.jar:0.10.0-SNAPSHOT-8bbf93aa4377dbdf597e7940670893330452b33f]
        at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:167) [pinot-all-0.10.0-SNAPSHOT-jar-with-dependencies.jar:0.10.0-SNAPSHOT-8bbf93aa4377dbdf597e7940670893330452b33f]
        at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$TypeOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:219) [pinot-all-0.10.0-SNAPSHOT-jar-with-dependencies.jar:0.10.0-SNAPSHOT-8bbf93aa4377dbdf597e7940670893330452b33
f]
        at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:79) [pinot-all-0.10.0-SNAPSHOT-jar-with-dependencies.jar:0.10.0-SNAPSHOT-8bbf93aa4377dbdf597e7940670893330452b33f]
        at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:469) [pinot-all-0.10.0-SNAPSHOT-jar-with-dependencies.jar:0.10.0-SNAPSHOT-8bbf93aa4377dbdf597e7940670893330452b33f]
        at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:391) [pinot-all-0.10.0-SNAPSHOT-jar-with-dependencies.jar:0.10.0-SNAPSHOT-8bbf93aa4377dbdf597e7940670893330452b33f]
        at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:80) [pinot-all-0.10.0-SNAPSHOT-jar-with-dependencies.jar:0.10.0-SNAPSHOT-8bbf93aa4377dbdf597e7940670893330452b33f]
        at org.glassfish.jersey.server.ServerRuntime$1.run(ServerRuntime.java:253) [pinot-all-0.10.0-SNAPSHOT-jar-with-dependencies.jar:0.10.0-SNAPSHOT-8bbf93aa4377dbdf597e7940670893330452b33f]
        at org.glassfish.jersey.internal.Errors$1.call(Errors.java:248) [pinot-all-0.10.0-SNAPSHOT-jar-with-dependencies.jar:0.10.0-SNAPSHOT-8bbf93aa4377dbdf597e7940670893330452b33f]
        at org.glassfish.jersey.internal.Errors$1.call(Errors.java:244) [pinot-all-0.10.0-SNAPSHOT-jar-with-dependencies.jar:0.10.0-SNAPSHOT-8bbf93aa4377dbdf597e7940670893330452b33f]
        at org.glassfish.jersey.internal.Errors.process(Errors.java:292) [pinot-all-0.10.0-SNAPSHOT-jar-with-dependencies.jar:0.10.0-SNAPSHOT-8bbf93aa4377dbdf597e7940670893330452b33f]
        at org.glassfish.jersey.internal.Errors.process(Errors.java:274) [pinot-all-0.10.0-SNAPSHOT-jar-with-dependencies.jar:0.10.0-SNAPSHOT-8bbf93aa4377dbdf597e7940670893330452b33f]
        at org.glassfish.jersey.internal.Errors.process(Errors.java:244) [pinot-all-0.10.0-SNAPSHOT-jar-with-dependencies.jar:0.10.0-SNAPSHOT-8bbf93aa4377dbdf597e7940670893330452b33f]
        at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:265) [pinot-all-0.10.0-SNAPSHOT-jar-with-dependencies.jar:0.10.0-SNAPSHOT-8bbf93aa4377dbdf597e7940670893330452b33f]
        at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:232) [pinot-all-0.10.0-SNAPSHOT-jar-with-dependencies.jar:0.10.0-SNAPSHOT-8bbf93aa4377dbdf597e7940670893330452b33f]
        at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:679) [pinot-all-0.10.0-SNAPSHOT-jar-with-dependencies.jar:0.10.0-SNAPSHOT-8bbf93aa4377dbdf597e7940670893330452b33f]
        at org.glassfish.jersey.grizzly2.httpserver.GrizzlyHttpContainer.service(GrizzlyHttpContainer.java:353) [pinot-all-0.10.0-SNAPSHOT-jar-with-dependencies.jar:0.10.0-SNAPSHOT-8bbf93aa4377dbdf597e7940670893330452b33f]
        at org.glassfish.grizzly.http.server.HttpHandler$1.run(HttpHandler.java:200) [pinot-all-0.10.0-SNAPSHOT-jar-with-dependencies.jar:0.10.0-SNAPSHOT-8bbf93aa4377dbdf597e7940670893330452b33f]
        at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:569) [pinot-all-0.10.0-SNAPSHOT-jar-with-dependencies.jar:0.10.0-SNAPSHOT-8bbf93aa4377dbdf597e7940670893330452b33f]
        at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:549) [pinot-all-0.10.0-SNAPSHOT-jar-with-dependencies.jar:0.10.0-SNAPSHOT-8bbf93aa4377dbdf597e7940670893330452b33f]
        at java.lang.Thread.run(Thread.java:829) [?:?]
Caused by: java.net.SocketTimeoutException: Read timed out
        at java.net.SocketInputStream.socketRead0(Native Method) ~[?:?]
Also I see some zk disconnections:
Copy code
Consumed 0 events from (rate:0.0/s), currentOffset=894238198, numRowsConsumedSoFar=555294, numRowsIndexedSoFar=555294
[Consumer clientId=consumer-null-2, groupId=null] Seeking to offset 894406661 for partition email-raw-events-62
[Consumer clientId=consumer-null-53, groupId=null] Seeking to offset 894229286 for partition email-raw-events-98
Consumed 0 events from (rate:0.0/s), currentOffset=894328031, numRowsConsumedSoFar=645137, numRowsIndexedSoFar=645137
[Consumer clientId=consumer-null-52, groupId=null] Seeking to offset 894221230 for partition email-raw-events-86
[Consumer clientId=consumer-null-58, groupId=null] Seeking to offset 894238198 for partition email-raw-events-26
[Consumer clientId=consumer-null-43, groupId=null] Seeking to offset 894338250 for partition email-raw-events-68
zookeeper state changed (Disconnected)
I don’t see any issues on the ZK cluster. Any pointers ?
r
hi I'll take a look and get back to you
k
Thanks @Richard Startin
m
ZK disconnects usually happen if the servers are GC’ing. Can you check on that @kaivalya apte?
r
@kaivalya apte you can capture gc pause times without restarting by running 
jcmd <controller pid> JFR.start duration=60s filename=controller.jfr settings=profile
k
Thanks @Mayank and @Richard Startin let me use this and see what I get.
r
also the error log comes from an external facing API 
/table/{tableName}/size
which is usually called by pinot UI if you open the pinot controller link. this doesn't seem to be the root cause but rather an indicator that the server has already gone dead.
👍 1
were you able to check the server log?
k
were you able to check the server log?
Yeah server logs doesn’t say much, it has no errors/exceptions. It mainly has 
seeking offset
logs.
@Richard Startin - I started recording the GC pause times.
some servers already DIED.. I am almost sure those are GCing (as @Mayank pointed). How do I make sense of the profile file at 
/opt/pinot/controller.jfr
(also sorry couldn’t work on it yesterday, got distracted on some other things)
r
can you collect the flight recording please
we're just guessing otherwise
k
collect the flight recording please
Sorry, to be sure, do you mean get that file and paste it here ?
ok I am trying to visualize the jfr
ok I am not sure I captured the right thing. I had to run jcmd from the controller right?
controller.jfr
controller.jfr
Logs from the server that got disconnected (marked as DEAD)
Copy code
2022-02-22T10:27:42.997Z | Socket connection established, initiating session, client: /172.25.35.164:26470, server: zk-email-pinot-qa.zk.svc.test01.k8s.run/172.25.35.245:2181
2022-02-22T10:27:42.999Z | Session establishment complete on server zk-email-pinot-qa.zk.svc.test01.k8s.run/172.25.35.245:2181, sessionid = 0x200117582b601f7, negotiated timeout = 30000
2022-02-22T10:27:42.999Z | zookeeper state changed (SyncConnected)
2022-02-22T10:27:43.000Z | Handling new session, session id: 200117582b601f7, instance: Server_analytics-pinot-server-4.analytics-pinot-server.email-pinot.svc.test01.k8s.run_8098, instanceTye: PARTICIPANT, cluster: analytics-pinot
2022-02-22T10:27:43.000Z | Consumed 1000 events from (rate:8.317184/s), currentOffset=894435681, numRowsConsumedSoFar=752757, numRowsIndexedSoFar=752757
2022-02-22T10:27:43.000Z | Stop ParticipantHealthReportTimerTask
2022-02-22T10:27:43.000Z | [Consumer clientId=consumer-null-43, groupId=null] Seeking to offset 894435681 for partition email-raw-events-83
2022-02-22T10:27:43.000Z | Resetting CallbackHandler: org.apache.helix.manager.zk.CallbackHandler@360f0f0e. Is resetting for shutdown: false.
2022-02-22T10:27:43.000Z | 61 START:INVOKE /analytics-pinot/INSTANCES/Server_analytics-pinot-server-4.analytics-pinot-server.email-pinot.svc.test01.k8s.run_8098/MESSAGES listener:org.apache.helix.messaging.handling.HelixTaskExecutor@18c1fcbc type: FINALIZE
2022-02-22T10:27:43.000Z | Subscribing changes listener to path: /analytics-pinot/INSTANCES/Server_analytics-pinot-server-4.analytics-pinot-server.email-pinot.svc.test01.k8s.run_8098/MESSAGES, type: FINALIZE, listener: org.apache.helix.messaging.handling.HelixTaskExecutor@18c1fcbc
2022-02-22T10:27:43.000Z | Subscribing child change listener to path:/analytics-pinot/INSTANCES/Server_analytics-pinot-server-4.analytics-pinot-server.email-pinot.svc.test01.k8s.run_8098/MESSAGES
2022-02-22T10:27:43.000Z | Server_analytics-pinot-server-4.analytics-pinot-server.email-pinot.svc.test01.k8s.run_8098 unsubscribe child-change. path: /analytics-pinot/INSTANCES/Server_analytics-pinot-server-4.analytics-pinot-server.email-pinot.svc.test01.k8s.run_8098/MESSAGES, listener: org.apache.helix.messaging.handling.HelixTaskExecutor@18c1fcbc
2022-02-22T10:27:43.000Z | Subscribing to path:/analytics-pinot/INSTANCES/Server_analytics-pinot-server-4.analytics-pinot-server.email-pinot.svc.test01.k8s.run_8098/MESSAGES took:0
2022-02-22T10:27:43.000Z | Reset HelixTaskExecutor
2022-02-22T10:27:43.000Z | Unregistering ClusterStatus:cluster=analytics-pinot,messageQueue=Server_analytics-pinot-server-4.analytics-pinot-server.email-pinot.svc.test01.k8s.run_8098
2022-02-22T10:27:43.001Z | MBean HelixThreadPoolExecutor:Type=USER_DEFINE_MSG has been un-registered.
2022-02-22T10:27:43.001Z | Reset exectuor for msgType: USER_DEFINE_MSG, pool: java.util.concurrent.ThreadPoolExecutor@146371cb[Running, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0]
2022-02-22T10:27:43.001Z | Shutting down pool: java.util.concurrent.ThreadPoolExecutor@146371cb[Running, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0]
2022-02-22T10:27:43.001Z | Reset called
2022-02-22T10:27:43.001Z | MBean HelixThreadPoolExecutor:Type=TASK_REPLY has been un-registered.
2022-02-22T10:27:43.001Z | Reset exectuor for msgType: TASK_REPLY, pool: java.util.concurrent.ThreadPoolExecutor@553463d3[Running, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0]
2022-02-22T10:27:43.001Z | Shutting down pool: java.util.concurrent.ThreadPoolExecutor@553463d3[Running, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0]
2022-02-22T10:27:43.001Z | MBean HelixThreadPoolExecutor:Type=STATE_TRANSITION has been un-registered.
2022-02-22T10:27:43.001Z | Reset exectuor for msgType: STATE_TRANSITION, pool: java.util.concurrent.ThreadPoolExecutor@565e0d2c[Running, pool size = 40, active threads = 0, queued tasks = 0, completed tasks = 96]
2022-02-22T10:27:43.001Z | Shutting down pool: java.util.concurrent.ThreadPoolExecutor@565e0d2c[Running, pool size = 40, active threads = 0, queued tasks = 0, completed tasks = 96]
2022-02-22T10:27:43.001Z | [Consumer clientId=consumer-null-43, groupId=null] Seeking to offset 894435688 for partition email-raw-events-83
2022-02-22T10:27:49.758Z | [Consumer clientId=consumer-null-31, groupId=null] Seeking to offset 894287770 for partition email-raw-events-35
2022-02-22T10:27:49.758Z | [Consumer clientId=consumer-null-6, groupId=null] Seeking to offset 894252566 for partition email-raw-events-59
2022-02-22T10:27:49.758Z | [Consumer clientId=consumer-null-4, groupId=null] Seeking to offset 894270784 for partition email-raw-events-29
2022-02-22T10:27:49.758Z | [Consumer clientId=consumer-null-20, groupId=null] Seeking to offset 894294749 for partition email-raw-events-53
2022-02-22T10:27:49.758Z | [Consumer clientId=consumer-null-37, groupId=null] Seeking to offset 894284141 for partition email-raw-events-95
2022-02-22T10:27:49.758Z | [Consumer clientId=consumer-null-40, groupId=null] Seeking to offset 894304673 for partition email-raw-events-89
2022-02-22T10:28:03.094Z | Client session timed out, have not heard from server in 20095ms for sessionid 0x200117582b601f7
2022-02-22T10:28:03.095Z | Client session timed out, have not heard from server in 20095ms for sessionid 0x200117582b601f7, closing socket connection and attempting reconnect
2022-02-22T10:28:09.809Z | [Consumer clientId=consumer-null-31, groupId=null] Seeking to offset 894287770 for partition email-raw-events-35
2022-02-22T10:28:09.809Z | [Consumer clientId=consumer-null-43, groupId=null] Seeking to offset 894435688 for partition email-raw-events-83
2022-02-22T10:28:16.441Z | zookeeper state changed (Disconnected)
2022-02-22T10:28:29.763Z | [Consumer clientId=consumer-null-31, groupId=null] Seeking to offset 894287770 for partition email-raw-events-35
2022-02-22T10:28:29.763Z | [Consumer clientId=consumer-null-43, groupId=null] Error sending fetch request (sessionId=243448617, epoch=255) to node 17:
2022-02-22T10:28:29.763Z | org.apache.kafka.common.errors.DisconnectException: null
2022-02-22T10:28:29.763Z | [Consumer clientId=consumer-null-6, groupId=null] Error sending fetch request (sessionId=958254965, epoch=INITIAL) to node 9:
2022-02-22T10:28:29.763Z | org.apache.kafka.common.errors.DisconnectException: null
2022-02-22T10:28:29.763Z | [Consumer clientId=consumer-null-4, groupId=null] Error sending fetch request (sessionId=1077599285, epoch=INITIAL) to node 12:
2022-02-22T10:28:29.763Z | org.apache.kafka.common.errors.TimeoutException: Failed to send request after 30000 ms.
r
set xms=xmx, you have xms=8G and xmx=16G, resizing the heap is an STW event
👀 1
no gcs recorded during those 60s though
k
yeah.. why would that trigger a disconnect from zk? zk timeout is set to 10sec
I took another jfr and found no GC
r
there are some very long compiles in this recording, >1s
k
what tool are you using to read the jfr? I am using visual vm
r
but it doesn't look like there's anything in the recording which should cause zk disconnects
jmc
k
here is another one that I got.
controller-new.jfr
👀 1
r
there's basically nothing in that recording, no GCs, no compiles, no method profiling but yammer metrics
are you sure the networking setup is correct
k
hmm.. yes its been running well for days (at low ingestion rate).
When I restart the servers they connect back and are able to serve queries.
until I start the ingestion.
but one thing is that CPU usage for those servers shoots up at ingestion. I have segment flush threshold at 1G and 6h (but I have also tried with other smaller variants)
are you sure the networking setup is correct
Can you please elaborate what should I check to make sure this is correct?
also why wouldn’t servers try to reconnect? I don’t see any errors stating something like “unable to connect” , but they do connect on restarts.
ok maybe servers try to reconnect, but somehow don’t succeed.
Copy code
2022-02-22T11:09:52.945Z | 2022-02-22 11:09:52,944 [myid:5] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@222] - Accepted socket connection from /172.25.32.141:53550
2022-02-22T11:09:52.945Z | 2022-02-22 11:09:52,945 [myid:5] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@942] - Client attempting to renew session 0x200117582b601fe at /172.25.32.141:53550
2022-02-22T11:09:52.945Z | 2022-02-22 11:09:52,945 [myid:5] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:Learner@108] - Revalidating client: 0x200117582b601fe
2022-02-22T11:09:52.945Z | 2022-02-22 11:09:52,945 [myid:5] - INFO [QuorumPeer[myid=5]/0.0.0.0:2181:ZooKeeperServer@687] - Invalid session 0x200117582b601fe for client /172.25.32.141:53550, probably expired
2022-02-22T11:09:52.945Z | 2022-02-22 11:09:52,945 [myid:5] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1056] - Closed socket connection for client /172.25.32.141:53550 which had sessionid 0x200117582b601fe
2022-02-22T11:09:52.947Z | 2022-02-22 11:09:52,947 [myid:5] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@222] - Accepted socket connection from /172.25.32.141:53552
2022-02-22T11:09:54.779Z | 2022-02-22 11:09:54,778 [myid:5] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@222] - Accepted socket connection from /172.25.35.245:33846
2022-02-22T11:09:54.779Z | 2022-02-22 11:09:54,779 [myid:5] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@908] - Processing ruok command from /172.25.35.245:33846
2022-02-22T11:09:54.779Z | 2022-02-22 11:09:54,779 [myid:5] - INFO [Thread-89588:NIOServerCnxn@1056] - Closed socket connection for client /172.25.35.245:33846 (no session established for client)
2022-02-22T11:09:59.310Z | 2022-02-22 11:09:59,309 [myid:5] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@949] - Client attempting to establish new session at /172.25.32.141:53552
2022-02-22T11:09:59.311Z | 2022-02-22 11:09:59,311 [myid:5] - INFO [CommitProcessor:5:ZooKeeperServer@694] - Established session 0x50014be61d40205 with negotiated timeout 30000 for client /172.25.32.141:53552
2022-02-22T11:10:02.216Z | 2022-02-22 11:10:02,216 [myid:5] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@222] - Accepted socket connection from /127.0.0.1:11488
2022-02-22T11:10:02.216Z | 2022-02-22 11:10:02,216 [myid:5] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@908] - Processing ruok command from /127.0.0.1:11488
2022-02-22T11:10:02.217Z | 2022-02-22 11:10:02,217 [myid:5] - INFO [Thread-89589:NIOServerCnxn@1056] - Closed socket connection for client /127.0.0.1:11488 (no session established for client)
2022-02-22T11:10:12.228Z | 2022-02-22 11:10:12,227 [myid:5] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@222] - Accepted socket connection from /127.0.0.1:11604
2022-02-22T11:10:12.228Z | 2022-02-22 11:10:12,227 [myid:5] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@908] - Processing ruok command from /127.0.0.1:11604
2022-02-22T11:10:12.228Z | 2022-02-22 11:10:12,228 [myid:5] - INFO [Thread-89590:NIOServerCnxn@1056] - Closed socket connection for client /127.0.0.1:11604 (no session established for client)
2022-02-22T11:10:12.866Z | 2022-02-22 11:10:12,866 [myid:5] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@222] - Accepted socket connection from /172.25.13.120:24172
2022-02-22T11:10:12.867Z | 2022-02-22 11:10:12,866 [myid:5] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@908] - Processing ruok command from /172.25.13.120:24172
2022-02-22T11:10:12.867Z | 2022-02-22 11:10:12,867 [myid:5] - INFO [Thread-89591:NIOServerCnxn@1056] - Closed socket connection for client /172.25.13.120:24172 (no session established for client)
2022-02-22T11:10:22.269Z | 2022-02-22 11:10:22,269 [myid:5] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@222] - Accepted socket connection from /127.0.0.1:11744
2022-02-22T11:10:22.269Z | 2022-02-22 11:10:22,269 [myid:5] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@908] - Processing srvr command from /127.0.0.1:11744
2022-02-22T11:10:22.269Z | 2022-02-22 11:10:22,269 [myid:5] - INFO [Thread-89592:NIOServerCnxn@1056] - Closed socket connection for client /127.0.0.1:11744 (no session established for client)
2022-02-22T11:10:22.270Z | 2022-02-22 11:10:22,269 [zookeeper_readiness_probe:5] INFO - srvr response: Zookeeper version: 3.4.14-6417b43ed6b60cb38117f5d3669566c50cafaf0c, built on 06/04/2019 15:08 GMT
2022-02-22T11:10:22.270Z | Latency min/avg/max: 0/0/52
2022-02-22T11:10:22.270Z | Received: 7630352
2022-02-22T11:10:22.270Z | Sent: 7658605
2022-02-22T11:10:22.270Z | Connections: 3
2022-02-22T11:10:22.270Z | Outstanding: 0
2022-02-22T11:10:22.270Z | Zxid: 0x5005f3cde
2022-02-22T11:10:22.270Z | Mode: follower
2022-02-22T11:10:22.270Z | Node count: 2486
2022-02-22T11:10:22.270Z |
2022-02-22T11:10:22.568Z | 2022-02-22 11:10:22,568 [myid:5] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@222] - Accepted socket connection from /127.0.0.1:11750
2022-02-22T11:10:22.568Z | 2022-02-22 11:10:22,568 [myid:5] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@908] - Processing ruok command from /127.0.0.1:11750
2022-02-22T11:10:22.568Z | 2022-02-22 11:10:22,568 [myid:5] - INFO [Thread-89593:NIOServerCnxn@1056] - Closed socket connection for client /127.0.0.1:11750 (no session established for client)
r
if they connected in the first place the networking is probably ok
are the zk servers responsive?
k
yeah I would assume that
Copy code
2022-02-22T11:09:52.945Z | 2022-02-22 11:09:52,945 [myid:5] - INFO [QuorumPeer[myid=5]/0.0.0.0:2181:ZooKeeperServer@687] - Invalid session 0x200117582b601fe for client /172.25.32.141:53550, probably expired
^ this looks concerning
yes zk servers are responsive, metrics look fine.
I am using kubernetes helm charts to deploy but with an existing zk cluster
r
whenever I've seen this happen before (with pinot and with other zk coordinated systems e.g. HDFS) it has tended to be either ZK or the client GCing
so I'm not sure, I'll flag it for someone else to look at later when California wakes up
k
Meanwhile I will try to deploy a Zk cluster (where I have more control on) and dig deeper. Thanks @Richard Startin for looking at this and helping out 🙂
So I created a new Zk cluster instead of using existing Zk cluster and so far the processing is looking wayyy better. None of the servers has gone DEAD, none of the segments have gone BAD and the ingestion rate is also fine (200k/sec). If this keeps like this for the entire day I’d be very happy, but still not sure what was going on with the old Zk cluster 🤔 . I will post an update here in any case.
Hmm.. it stayed longer this time, but then zookeeper started refusing connections. 😞 Not sure if this is about Zk or pinot.
Copy code
2022-02-22 13:52:44,510 [myid:1] - INFO  [SessionTracker:ZooKeeperServer@628] - Expiring session 0x1007f106cc50082, timeout of 30000ms exceeded
2022-02-22 13:52:57,829 [myid:1] - INFO  [NIOWorkerThread-2:ZooKeeperServer@1429] - Refusing session request for client /172.25.28.78:26918 as it has seen zxid 0x404b our last zxid is 0x11f client must try another server
2022-02-22 13:53:26,702 [myid:1] - INFO  [NIOWorkerThread-6:ZooKeeperServer@1429] - Refusing session request for client /172.25.2.148:8099 as it has seen zxid 0x41ae our last zxid is 0x11f client must try another server
2022-02-22 13:53:47,350 [myid:1] - INFO  [NIOWorkerThread-3:ZooKeeperServer@1429] - Refusing session request for client /172.25.2.148:51458 as it has seen zxid 0x41ae our last zxid is 0x123 client must try another server
2022-02-22 13:54:36,188 [myid:1] - WARN  [NIOWorkerThread-1:NIOServerCnxn@371] - Unexpected exception
EndOfStreamException: Unable to read additional data from client, it probably closed the socket: address = /172.25.32.141:26797, session = 0x1007f106cc50085
        at org.apache.zookeeper.server.NIOServerCnxn.handleFailedRead(NIOServerCnxn.java:170)
        at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:333)
        at org.apache.zookeeper.server.NIOServerCnxnFactory$IOWorkRequest.doWork(NIOServerCnxnFactory.java:508)
        at org.apache.zookeeper.server.WorkerService$ScheduledWorkRequest.run(WorkerService.java:154)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:829)
2022-02-22 13:55:00,510 [myid:1] - INFO  [SessionTracker:ZooKeeperServer@628] - Expiring session 0x1007f106cc50085, timeout of 30000ms exceeded
2022-02-22 13:55:23,282 [myid:1] - INFO  [NIOWorkerThread-6:ZooKeeperServer@1077] - Invalid session 0x1007f106cc50085 for client /172.25.32.141:31989, probably expired
2022-02-22 13:55:43,590 [myid:1] - INFO  [NIOWorkerThread-3:ZooKeeperServer@1429] - Refusing session request for client /172.25.2.148:55332 as it has seen zxid 0x41ae our last zxid is 0x125 client must try another server
2022-02-22 13:55:47,640 [myid:1] - INFO  [NIOWorkerThread-1:ZooKeeperServer@1429] - Refusing session request for client /172.25.41.151:59759 as it has seen zxid 0x41ae our last zxid is 0x125 client must try another server
2022-02-22 13:55:52,449 [myid:1] - WARN  [NIOWorkerThread-5:NIOServerCnxn@371] - Unexpected exception
EndOfStreamException: Unable to read additional data from client, it probably closed the socket: address = /172.25.6.40:34916, session = 0x1007f106cc50087
        at org.apache.zookeeper.server.NIOServerCnxn.handleFailedRead(NIOServerCnxn.java:170)
        at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:333)
        at org.apache.zookeeper.server.NIOServerCnxnFactory$IOWorkRequest.doWork(NIOServerCnxnFactory.java:508)
        at org.apache.zookeeper.server.WorkerService$ScheduledWorkRequest.run(WorkerService.java:154)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:829)
2022-02-22 13:55:54,511 [myid:1] - INFO  [SessionTracker:ZooKeeperServer@628] - Expiring session 0x1007f106cc50087, timeout of 30000ms exceeded
2022-02-22 13:56:17,683 [myid:1] - INFO  [NIOWorkerThread-8:ZooKeeperServer@1429] - Refusing session request for client /172.25.2.148:4953 as it has seen zxid 0x41ae our last zxid is 0x127 client must try another server
2022-02-22 13:56:27,110 [myid:1] - WARN  [NIOWorkerThread-2:NIOServerCnxn@371] - Unexpected exception
EndOfStreamException: Unable to read additional data from client, it probably closed the socket: address = /172.25.29.156:42354, session = 0x1007f106cc50088
        at org.apache.zookeeper.server.NIOServerCnxn.handleFailedRead(NIOServerCnxn.java:170)
        at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:333)
        at org.apache.zookeeper.server.NIOServerCnxnFactory$IOWorkRequest.doWork(NIOServerCnxnFactory.java:508)
        at org.apache.zookeeper.server.WorkerService$ScheduledWorkRequest.run(WorkerService.java:154)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:829)
2022-02-22 13:56:36,510 [myid:1] - INFO  [SessionTracker:ZooKeeperServer@628] - Expiring session 0x1007f106cc50088, timeout of 30000ms exceeded
2022-02-22 13:56:42,786 [myid:1] - INFO  [NIOWorkerThread-4:ZooKeeperServer@1429] - Refusing session request for client /172.25.41.151:26863 as it has seen zxid 0x41ae our last zxid is 0x129 client must try another server
2022-02-22 13:58:00,314 [myid:1] - INFO  [NIOWorkerThread-2:ZooKeeperServer@1429] - Refusing session request for client /172.25.2.148:12574 as it has seen zxid 0x41ae our last zxid is 0x129 client must try another server
2022-02-22 13:58:11,618 [myid:1] - INFO  [NIOWorkerThread-6:ZooKeeperServer@1429] - Refusing session request for client /172.25.44.226:57808 as it has seen zxid 0x4232 our last zxid is 0x12a client must try another server
2022-02-22 13:58:24,448 [myid:1] - WARN  [NIOWorkerThread-1:NIOServerCnxn@371] - Unexpected exception
EndOfStreamException: Unable to read additional data from client, it probably closed the socket: address = /172.25.32.141:30267, session = 0x1007f106cc50089
        at org.apache.zookeeper.server.NIOServerCnxn.handleFailedRead(NIOServerCnxn.java:170)
        at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:333)
        at org.apache.zookeeper.server.NIOServerCnxnFactory$IOWorkRequest.doWork(NIOServerCnxnFactory.java:508)
        at org.apache.zookeeper.server.WorkerService$ScheduledWorkRequest.run(WorkerService.java:154)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:829)
➜  helm git:(email-analytics) ✗
Open in Slack
PreviousNext
Powered by