Hi team, it seems like our brokers are running into problems connecting with Zookeeper and they are going into crashloop. PFA the logs:

Hi Prashant, Is everything else working fine? Are you seeing same connection problems in controller or servers as well?

@Kartik Khare Yes, servers and controllers are working fine, only brokers are facing this issue.

@Jackie Seems like Helix is doing some weird things, I see this in logs which is then followed by a lot of InterruptedExceptions

2022/07/20 09:03:19.608 WARN [ZKMetadataProvider] [HelixTaskExecutor-message_handle_thread] Schema name does not match raw table name, schema name: serviceCallView, raw table name: service_call_view
2022/07/20 09:03:25.067 ERROR [HelixTaskExecutor] [Thread-38] Pool did not fully terminate in 200ms. pool: java.util.concurrent.ThreadPoolExecutor@2a8c7e4c[Shutting down, pool size = 4, active threads = 4, queued tasks = 0, completed tasks = 1]

2022/07/20 09:03:25.468 WARN [StateModel] [Thread-38] Default reset method invoked. Either because the process longer own this resource or session timedout

@Kartik Khare Yes, this appeared out-of-nowhere last week, and then again yesterday. No config changes to Pinot. ZK was running with high heap util (> 90%), we increased that. Increase the ZK connect timeout from 40s to 2m but didn’t help.

and if we add any new broker instance, it works fine, no issue in that

Here’s the logs of a new broker that restarted:

WARNING: All illegal access operations will be denied in a future release
2022/07/20 16:11:36.374 WARN [PinotMetricUtils] [Start a Pinot [BROKER]] More than one PinotMetricsFactory was found: [class org.apache.pinot.plugin.metrics.dropwizard.DropwizardMetricsFactory, class org.apache.pinot.plugin.metrics.yammer.YammerMetricsFactory]
Jul 20, 2022 4:11:39 PM org.glassfish.grizzly.http.server.NetworkListener start
INFO: Started listener bound to [0.0.0.0:8099]
Jul 20, 2022 4:11:39 PM org.glassfish.grizzly.http.server.HttpServer start
INFO: [HttpServer] Started.
2022/07/20 16:11:43.093 WARN [ParticipantHealthReportTask] [Start a Pinot [BROKER]] ParticipantHealthReportTimerTask already stopped
2022/07/20 16:11:43.244 WARN [CallbackHandler] [Start a Pinot [BROKER]] Callback handler received event in wrong order. Listener: org.apache.helix.messaging.handling.HelixTaskExecutor@6b42e381, path: /pinot-prod/INSTANCES/Broker_pinot-broker-1.broker-headless.pinot.svc.cluster.local_8099/MESSAGES, expected types: [CALLBACK, FINALIZE] but was INIT
2022/07/20 16:11:44.437 WARN [RoutingManager] [HelixTaskExecutor-message_handle_thread] Routing does not exist for table: span_event_view_1_REALTIME, skipping refreshing segment
2022/07/20 16:11:46.986 WARN [RoutingManager] [HelixTaskExecutor-message_handle_thread] Routing does not exist for table: backend_entity_view_REALTIME, skipping refreshing segment
2022/07/20 16:11:54.666 WARN [RoutingManager] [HelixTaskExecutor-message_handle_thread] Routing does not exist for table: raw_trace_view_REALTIME, skipping refreshing segment
2022/07/20 16:11:59.912 WARN [RoutingManager] [HelixTaskExecutor-message_handle_thread] Routing does not exist for table: span_event_view_1_REALTIME, skipping refreshing segment
2022/07/20 16:12:14.180 WARN [RoutingManager] [HelixTaskExecutor-message_handle_thread] Routing does not exist for table: span_event_view_1_REALTIME, skipping refreshing segment
2022/07/20 16:12:21.122 WARN [RoutingManager] [HelixTaskExecutor-message_handle_thread] Routing does not exist for table: raw_service_view_REALTIME, skipping refreshing segment
2022/07/20 16:12:22.460 WARN [RoutingManager] [HelixTaskExecutor-message_handle_thread] Routing does not exist for table: raw_trace_view_REALTIME, skipping refreshing segment
2022/07/20 16:12:29.167 WARN [RoutingManager] [HelixTaskExecutor-message_handle_thread] Routing does not exist for table: span_event_view_1_REALTIME, skipping refreshing segment
2022/07/20 16:12:29.805 WARN [RoutingManager] [HelixTaskExecutor-message_handle_thread] Routing does not exist for table: raw_trace_view_REALTIME, skipping refreshing segment
2022/07/20 16:12:32.150 WARN [RoutingManager] [HelixTaskExecutor-message_handle_thread] Routing does not exist for table: span_event_view_1_REALTIME, skipping refreshing segment
2022/07/20 16:12:33.485 WARN [RoutingManager] [HelixTaskExecutor-message_handle_thread] Routing does not exist for table: span_event_view_1_REALTIME, skipping refreshing segment
2022/07/20 16:12:35.502 WARN [RoutingManager] [HelixTaskExecutor-message_handle_thread] Routing does not exist for table: backend_entity_view_REALTIME, skipping refreshing segment
2022/07/20 16:12:48.091 WARN [RoutingManager] [HelixTaskExecutor-message_handle_thread] Routing does not exist for table: span_event_view_1_REALTIME, skipping refreshing segment
2022/07/20 16:13:05.733 WARN [ServiceStatus] [grizzly-http-server-2] Caught exception while reading the service status
java.lang.IllegalStateException: ZkClient already closed!
	at org.apache.helix.manager.zk.zookeeper.ZkClient.retryUntilConnected(ZkClient.java:1171) ~[pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.apache.helix.manager.zk.zookeeper.ZkClient.readData(ZkClient.java:1326) ~[pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.apache.helix.manager.zk.zookeeper.ZkClient.readData(ZkClient.java:1318) ~[pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.apache.helix.manager.zk.ZkBaseDataAccessor.get(ZkBaseDataAccessor.java:320) ~[pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.apache.helix.manager.zk.ZKHelixDataAccessor.getProperty(ZKHelixDataAccessor.java:290) ~[pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.apache.helix.manager.zk.ZKHelixAdmin.getResourceIdealState(ZKHelixAdmin.java:918) ~[pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.apache.pinot.common.utils.ServiceStatus$IdealStateMatchServiceStatusCallback.getResourceIdealState(ServiceStatus.java:464) ~[pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.apache.pinot.common.utils.ServiceStatus$IdealStateMatchServiceStatusCallback.evaluateResourceStatus(ServiceStatus.java:404) ~[pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.apache.pinot.common.utils.ServiceStatus$IdealStateMatchServiceStatusCallback.getServiceStatus(ServiceStatus.java:347) ~[pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.apache.pinot.common.utils.ServiceStatus$IdealStateAndCurrentStateMatchServiceStatusCallback.getServiceStatus(ServiceStatus.java:473) ~[pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.apache.pinot.common.utils.ServiceStatus$MultipleCallbackServiceStatusCallback.getServiceStatus(ServiceStatus.java:147) ~[pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.apache.pinot.common.utils.ServiceStatus$MapBasedMultipleCallbackServiceStatusCallback.getServiceStatus(ServiceStatus.java:182) ~[pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.apache.pinot.common.utils.ServiceStatus.getServiceStatus(ServiceStatus.java:84) ~[pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.apache.pinot.common.utils.ServiceStatus.getServiceStatus(ServiceStatus.java:71) ~[pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.apache.pinot.broker.api.resources.PinotBrokerHealthCheck.getBrokerHealth(PinotBrokerHealthCheck.java:53) ~[pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	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.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:124) [pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:167) [pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$TypeOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:219) [pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:79) [pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:469) [pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:391) [pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:80) [pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.glassfish.jersey.server.ServerRuntime$1.run(ServerRuntime.java:253) [pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.glassfish.jersey.internal.Errors$1.call(Errors.java:248) [pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.glassfish.jersey.internal.Errors$1.call(Errors.java:244) [pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.glassfish.jersey.internal.Errors.process(Errors.java:292) [pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.glassfish.jersey.internal.Errors.process(Errors.java:274) [pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.glassfish.jersey.internal.Errors.process(Errors.java:244) [pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:265) [pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:232) [pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:679) [pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.glassfish.jersey.grizzly2.httpserver.GrizzlyHttpContainer.service(GrizzlyHttpContainer.java:353) [pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.glassfish.grizzly.http.server.HttpHandler$1.run(HttpHandler.java:200) [pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:569) [pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:549) [pinot-all-0.9.1-jar-with-dependencies.jar:0.9.1-f8ec6f6f8eead03488d3f4d0b9501fc3c4232961]
	at java.lang.Thread.run(Thread.java:829) [?:?]

@Prashant Pandey Can you please check if the broker is encountering heavy GC? From the log, the broker was disconnected from ZK, and the most common cause for that is heavy GC, which freeze the broker and the broker fails the ZK heartbeat check

@Jackie checking

From the broker log, it is somehow disconnected from ZK. All the exceptions are caused by that, but I don't see the reason of disconnecting from the log. Can you try enabling the INFO log so that we can get more information?

Okay got the logs finally

can you add here as well

@Kartik Khare DMed you, might contain some confidential info that’s why

it would be great to know the root cause and the fix if the issue was resolved.

Hi Priyank, as per latest update, Broker was taking more time to start than the k8s health-check period set. Thus they were being declared unhealthy and getting killed by k8s. Increasing the initial-delay of health-check in k8s for broker pods solved the issue.

this isn't a fix right ? @Kartik Khare with 5m of readiness check delay, 4 pod will take 20m to come up. also with more segments, over time, wouldn't this time need increase again ?