helix icon indicating copy to clipboard operation
helix copied to clipboard

Published 20 hours ago • verified publisher icon apache

DROPPED State

Open bojanv55 opened this issue 3 years ago • 7 comments

I'm using the latest version of Helix, and I tried searching through the docs to see what should be done in case of a DROPPED state, but cannot really find it.

So far I saw that every state can end up in a DROPPED state, and my state model has the state to support this. I have 10 java processes running on 10 separate servers. Every process is consuming one of 10 possible partitions on rabbitmq (10 different queues). Now, sometimes it happens that one of the processes goes to this DROPPED state, and then one of the remaining 9 processes takes over the 10th queue. So in that case I have that 9 processes consume 10 queues, but the last process (that got DROPPED) is just hanging there doing nothing. Do I need to manually trigger process restart on DROPPED state - or does helix have some mechanisms to re-join the group and get back to ONLINE state by itself?

P.S. sorry for asking here, but IRC server is not active, and I tried sending messages to mailing list but no answer...

bojanv55 avatar Sep 28 '21 09:09 bojanv55

Hi @bojanv55,

Please let us know if you are using FULL_AUTO mode or the other rebalance mode first. If you are using the FULL_AUTO mode, then the controller is supposed to bring that partition back as long as it still exists in the IdealStates. One of the exceptions is the controller is blocked from doing so because of an ERROR partition in cluster or some resource limitations.

jiajunwang avatar Sep 28 '21 18:09 jiajunwang

@jiajunwang I'm using IdealState.RebalanceMode.FULL_AUTO

I can even paste log that was there when that happened (this is from process that was just hanging doing nothing due to being DROPPED)

2021-09-28T09:46:42.714+02:00 (INFO): CallbackHandler {} START: CallbackHandler {}, INVOKE {} listener: {} type: {}
2021-09-28T09:46:42.714+02:00 (INFO): CallbackHandler {} START: CallbackHandler {}, INVOKE {} listener: {} type: {}
2021-09-28T09:46:42.715+02:00 (INFO): CallbackHandler CallbackHandler {} subscribing changes listener to path: {}, callback type: {}, event types: {}, listener: {}, watchChild: {}
2021-09-28T09:46:42.715+02:00 (INFO): CallbackHandler CallbackHandler {} subscribing changes listener to path: {}, callback type: {}, event types: {}, listener: {}, watchChild: {}
2021-09-28T09:46:42.717+02:00 (INFO): CallbackHandler CallbackHandler{}, Subscribing to path: {} took: {}
2021-09-28T09:46:42.717+02:00 (INFO): CallbackHandler CallbackHandler{}, Subscribing to path: {} took: {}
2021-09-28T09:46:42.721+02:00 (INFO): MessageLatencyMonitor The latency of message b4ba7df0-9265-4b35-b643-e3f3d676d1e4 is 19 ms
2021-09-28T09:46:42.721+02:00 (INFO): MessageLatencyMonitor The latency of message b4ba7df0-9265-4b35-b643-e3f3d676d1e4 is 19 ms
2021-09-28T09:46:42.767+02:00 (INFO): HelixTaskExecutor Scheduling message {}: {}:{}, {}->{}
2021-09-28T09:46:42.767+02:00 (INFO): HelixTaskExecutor Scheduling message {}: {}:{}, {}->{}
2021-09-28T09:46:42.786+02:00 (INFO): HelixTaskExecutor Submit task: b4ba7df0-9265-4b35-b643-e3f3d676d1e4 to pool: java.util.concurrent.ThreadPoolExecutor@3b77fd8f[Running, pool size = 2, active threads = 0, queued 
tasks = 0, completed tasks = 2]
2021-09-28T09:46:42.786+02:00 (INFO): HelixTaskExecutor Submit task: b4ba7df0-9265-4b35-b643-e3f3d676d1e4 to pool: java.util.concurrent.ThreadPoolExecutor@3b77fd8f[Running, pool size = 2, active threads = 0, queued 
tasks = 0, completed tasks = 2]
2021-09-28T09:46:42.788+02:00 (INFO): HelixTaskExecutor Message: b4ba7df0-9265-4b35-b643-e3f3d676d1e4 handling task scheduled
2021-09-28T09:46:42.788+02:00 (INFO): HelixTaskExecutor Message: b4ba7df0-9265-4b35-b643-e3f3d676d1e4 handling task scheduled
2021-09-28T09:46:42.791+02:00 (INFO): HelixTask handling task: b4ba7df0-9265-4b35-b643-e3f3d676d1e4 begin, at: 1632815202788
2021-09-28T09:46:42.791+02:00 (INFO): HelixTask handling task: b4ba7df0-9265-4b35-b643-e3f3d676d1e4 begin, at: 1632815202788
2021-09-28T09:46:42.791+02:00 (INFO): CallbackHandler {} END:INVOKE CallbackHandler {}, {} listener: {} type: {} Took: {}ms
2021-09-28T09:46:42.791+02:00 (INFO): CallbackHandler {} END:INVOKE CallbackHandler {}, {} listener: {} type: {} Took: {}ms
2021-09-28T09:46:42.861+02:00 (INFO): HelixStateTransitionHandler handling message: b4ba7df0-9265-4b35-b643-e3f3d676d1e4 transit MyCompServiceResource.MyCompServiceResource_0|[] from:ONLINE to:OFFLINE, relay
edFrom: null
2021-09-28T09:46:42.861+02:00 (INFO): HelixStateTransitionHandler handling message: b4ba7df0-9265-4b35-b643-e3f3d676d1e4 transit MyCompServiceResource.MyCompServiceResource_0|[] from:ONLINE to:OFFLINE, relay
edFrom: null
2021-09-28T09:46:42.864+02:00 (INFO): ZNRecord Merging with delta list, recordId = MyCompServiceResource other:MyCompServiceResource
2021-09-28T09:46:42.864+02:00 (INFO): ZNRecord Merging with delta list, recordId = MyCompServiceResource other:MyCompServiceResource
2021-09-28T09:46:42.892+02:00 (INFO): HelixStateTransitionHandler Instance 10.200.32.108-1931, partition MyCompServiceResource_0 received state transition from ONLINE to OFFLINE on session 379ef96be64ff6f, messa
ge id: b4ba7df0-9265-4b35-b643-e3f3d676d1e4
2021-09-28T09:46:42.892+02:00 (INFO): HelixStateTransitionHandler Instance 10.200.32.108-1931, partition MyCompServiceResource_0 received state transition from ONLINE to OFFLINE on session 379ef96be64ff6f, messa
ge id: b4ba7df0-9265-4b35-b643-e3f3d676d1e4
2021-09-28T09:46:42.893+02:00 (INFO): OnlineOfflineStateModel Transitioning partition MyCompServiceResource_0 from ONLINE to OFFLINE state
2021-09-28T09:46:42.893+02:00 (INFO): OnlineOfflineStateModel Transitioning partition MyCompServiceResource_0 from ONLINE to OFFLINE state
2021-09-28T09:46:48.317+02:00 (INFO): HelixTask Message: {} (parent: {}) handling task for {}:{} completed at: {}, results: {}. FrameworkTime: {} ms; HandlerTime: {} ms.
2021-09-28T09:46:48.318+02:00 (INFO): CallbackHandler {} START: CallbackHandler {}, INVOKE {} listener: {} type: {}
2021-09-28T09:46:48.318+02:00 (INFO): CallbackHandler {} START: CallbackHandler {}, INVOKE {} listener: {} type: {}
2021-09-28T09:46:48.319+02:00 (INFO): CallbackHandler CallbackHandler {} subscribing changes listener to path: {}, callback type: {}, event types: {}, listener: {}, watchChild: {}
2021-09-28T09:46:48.319+02:00 (INFO): CallbackHandler CallbackHandler {} subscribing changes listener to path: {}, callback type: {}, event types: {}, listener: {}, watchChild: {}
2021-09-28T09:46:48.320+02:00 (INFO): CallbackHandler CallbackHandler{}, Subscribing to path: {} took: {}
2021-09-28T09:46:48.320+02:00 (INFO): CallbackHandler CallbackHandler{}, Subscribing to path: {} took: {}
2021-09-28T09:46:48.321+02:00 (INFO): HelixTaskExecutor No Messages to process
2021-09-28T09:46:48.321+02:00 (INFO): HelixTaskExecutor No Messages to process
2021-09-28T09:46:48.321+02:00 (INFO): CallbackHandler {} END:INVOKE CallbackHandler {}, {} listener: {} type: {} Took: {}ms
2021-09-28T09:46:48.321+02:00 (INFO): CallbackHandler {} END:INVOKE CallbackHandler {}, {} listener: {} type: {} Took: {}ms
yedFrom: null
2021-09-28T09:46:48.264+02:00 (INFO): ZNRecord Merging with delta list, recordId = MyCompServiceResource other:MyCompServiceResource
2021-09-28T09:46:48.264+02:00 (INFO): ZNRecord Merging with delta list, recordId = MyCompServiceResource other:MyCompServiceResource
2021-09-28T09:46:48.286+02:00 (INFO): HelixStateTransitionHandler Instance 10.200.32.108-1931, partition MyCompServiceResource_0 received state transition from OFFLINE to DROPPED on session 379ef96be64ff6f, mess
age id: 93472683-f9d5-4d70-b10e-d3f8c5e3b85a
2021-09-28T09:46:48.286+02:00 (INFO): HelixStateTransitionHandler Instance 10.200.32.108-1931, partition MyCompServiceResource_0 received state transition from OFFLINE to DROPPED on session 379ef96be64ff6f, mess
age id: 93472683-f9d5-4d70-b10e-d3f8c5e3b85a
2021-09-28T09:46:48.286+02:00 (INFO): OnlineOfflineStateModel Transitioning partition MyCompServiceResource_0 from OFFLINE to DROPPED state
2021-09-28T09:46:48.286+02:00 (INFO): OnlineOfflineStateModel Transitioning partition MyCompServiceResource_0 from OFFLINE to DROPPED state
2021-09-28T09:46:48.288+02:00 (INFO): ZNRecord Merging with delta list, recordId = MyCompServiceResource other:MyCompServiceResource
2021-09-28T09:46:48.288+02:00 (INFO): ZNRecord Merging with delta list, recordId = MyCompServiceResource other:MyCompServiceResource
2021-09-28T09:46:48.293+02:00 (INFO): GroupCommit Removed /lcoo_MyComp/INSTANCES/10.200.32.108-1931/CURRENTSTATES/379ef96be64ff6f/MyCompServiceResource
2021-09-28T09:46:48.293+02:00 (INFO): GroupCommit Removed /lcoo_MyComp/INSTANCES/10.200.32.108-1931/CURRENTSTATES/379ef96be64ff6f/MyCompServiceResource
2021-09-28T09:46:48.309+02:00 (INFO): HelixTask Message 93472683-f9d5-4d70-b10e-d3f8c5e3b85a completed.
2021-09-28T09:46:48.309+02:00 (INFO): HelixTask Message 93472683-f9d5-4d70-b10e-d3f8c5e3b85a completed.
2021-09-28T09:46:48.315+02:00 (INFO): HelixTask Delete message 93472683-f9d5-4d70-b10e-d3f8c5e3b85a from zk!
2021-09-28T09:46:48.315+02:00 (INFO): HelixTask Delete message 93472683-f9d5-4d70-b10e-d3f8c5e3b85a from zk!
2021-09-28T09:46:48.317+02:00 (INFO): HelixTaskExecutor message finished: 93472683-f9d5-4d70-b10e-d3f8c5e3b85a, took 59
2021-09-28T09:46:48.317+02:00 (INFO): HelixTaskExecutor message finished: 93472683-f9d5-4d70-b10e-d3f8c5e3b85a, took 59
2021-09-28T09:46:48.317+02:00 (INFO): HelixTask Message: {} (parent: {}) handling task for {}:{} completed at: {}, results: {}. FrameworkTime: {} ms; HandlerTime: {} ms.
2021-09-28T09:46:48.317+02:00 (INFO): HelixTask Message: {} (parent: {}) handling task for {}:{} completed at: {}, results: {}. FrameworkTime: {} ms; HandlerTime: {} ms.
2021-09-28T09:46:48.318+02:00 (INFO): CallbackHandler {} START: CallbackHandler {}, INVOKE {} listener: {} type: {}
2021-09-28T09:46:48.318+02:00 (INFO): CallbackHandler {} START: CallbackHandler {}, INVOKE {} listener: {} type: {}
2021-09-28T09:46:48.319+02:00 (INFO): CallbackHandler CallbackHandler {} subscribing changes listener to path: {}, callback type: {}, event types: {}, listener: {}, watchChild: {}
2021-09-28T09:46:48.319+02:00 (INFO): CallbackHandler CallbackHandler {} subscribing changes listener to path: {}, callback type: {}, event types: {}, listener: {}, watchChild: {}
2021-09-28T09:46:48.320+02:00 (INFO): CallbackHandler CallbackHandler{}, Subscribing to path: {} took: {}
2021-09-28T09:46:48.320+02:00 (INFO): CallbackHandler CallbackHandler{}, Subscribing to path: {} took: {}
2021-09-28T09:46:48.321+02:00 (INFO): HelixTaskExecutor No Messages to process
2021-09-28T09:46:48.321+02:00 (INFO): HelixTaskExecutor No Messages to process
2021-09-28T09:46:48.321+02:00 (INFO): CallbackHandler {} END:INVOKE CallbackHandler {}, {} listener: {} type: {} Took: {}ms
2021-09-28T09:46:48.321+02:00 (INFO): CallbackHandler {} END:INVOKE CallbackHandler {}, {} listener: {} type: {} Took: {}ms

How could I check if there is an ERROR in cluster or limitation next time that this happens?

bojanv55 avatar Sep 28 '21 19:09 bojanv55

I would suggest exploring what the controller side log has. First of all, controller will print if anything blocks the rebalance pipeline so it has to early terminate. Secondly, you should be able to find some other clues by searching with the partition name (MyCompServiceResource_0) in the controller log. And please ensure that "MyCompServiceResource_0" is still in the list field of the Resource's IdealStates.

jiajunwang avatar Sep 28 '21 20:09 jiajunwang

@jiajunwang

I'm using InstanceType.CONTROLLER_PARTICIPANT for all the processes. So I guess all the processes can be either/either. Do you talk about the process that was the leader (I guess it is equal to controller) at that point in time?

bojanv55 avatar Sep 28 '21 20:09 bojanv55

Humm, I guess we are using little bit different terms here. So the controller is the instance (not necessarily a separate host though), that is managing the cluster. However, a controller won't take any resource partitions. The participant instance joining the cluster and can be assigned partitions by the controller instance.

In the zookeeper, there should be a CONTROLLER znode in the cluster's folder. And the instance that puts its information there is the controller that I meant.

I believe the key is to figure out what caused the controller to drop the partition. If possible, please provide the IdealState of the resource/the live instance list before and after so we can help to take a look.

jiajunwang avatar Sep 28 '21 23:09 jiajunwang

So, this is the log from CONTROLLER that lead it to trigger transition of that partition from ONLINE to OFFLINE (that is the last line in the log)

September 28th 2021, 09:46:42.419	CallbackHandler {} START: CallbackHandler {}, INVOKE {} listener: {} type: {}
September 28th 2021, 09:46:42.420	GenericHelixController START: GenericClusterController.onStateChange()
September 28th 2021, 09:46:42.421	CallbackHandler {} END:INVOKE CallbackHandler {}, {} listener: {} type: {} Took: {}ms
September 28th 2021, 09:46:42.421	GenericHelixController Controller stopping periodical rebalance timer at period 9223372036854775807
September 28th 2021, 09:46:42.421	GenericHelixController Controller stopping periodical rebalance timer at period 9223372036854775807
September 28th 2021, 09:46:42.421	GenericHelixController END: GenericClusterController.onStateChange()
September 28th 2021, 09:46:42.421	GenericHelixController START: Invoking {} controller pipeline for cluster: {}. Event type: {}, ID: {}. Event session ID: {}
September 28th 2021, 09:46:42.422	BaseControllerDataProvider Event 571eecc4_TASK : No ideal state change for lcoo_MyComp cluster, TASK pipeline
September 28th 2021, 09:46:42.422	GenericHelixController START: Invoking {} controller pipeline for cluster: {}. Event type: {}, ID: {}. Event session ID: {}
September 28th 2021, 09:46:42.422	BaseControllerDataProvider Event 571eecc4_DEFAULT : No ideal state change for lcoo_MyComp cluster, DEFAULT pipeline
September 28th 2021, 09:46:42.422	BaseControllerDataProvider Event 571eecc4_DEFAULT : No ClusterConfig change for cluster lcoo_MyComp, pipeline DEFAULT
September 28th 2021, 09:46:42.422	BaseControllerDataProvider Event 571eecc4_TASK : No ClusterConfig change for cluster lcoo_MyComp, pipeline TASK
September 28th 2021, 09:46:42.423	BaseControllerDataProvider Event 571eecc4_TASK : No resource config change for lcoo_MyComp cluster, TASK pipeline
September 28th 2021, 09:46:42.423	BaseControllerDataProvider Event 571eecc4_TASK : No instance config change for lcoo_MyComp cluster, TASK pipeline
September 28th 2021, 09:46:42.423	BaseControllerDataProvider Event 571eecc4_TASK : No live instance change for lcoo_MyComp cluster, TASK pipeline
September 28th 2021, 09:46:42.423	BaseControllerDataProvider Event 571eecc4_DEFAULT : No resource config change for lcoo_MyComp cluster, DEFAULT pipeline
September 28th 2021, 09:46:42.423	BaseControllerDataProvider Event 571eecc4_DEFAULT : No instance config change for lcoo_MyComp cluster, DEFAULT pipeline
September 28th 2021, 09:46:42.423	BaseControllerDataProvider Event 571eecc4_DEFAULT : No live instance change for lcoo_MyComp cluster, DEFAULT pipeline
September 28th 2021, 09:46:42.426	PropertyCache Event lcoo_MyComp::TASK::571eecc4_TASK : Refreshed 7 property StateModelDefinition took 3 ms. Selective: false
September 28th 2021, 09:46:42.427	PropertyCache Event lcoo_MyComp::TASK::571eecc4_TASK : Refreshed 0 property ClusterConstraint took 0 ms. Selective: false
September 28th 2021, 09:46:42.427	PropertyCache Event lcoo_MyComp::DEFAULT::571eecc4_DEFAULT : Refreshed 7 property StateModelDefinition took 4 ms. Selective: false
September 28th 2021, 09:46:42.428	InstanceMessagesCache START: InstanceMessagesCache.refresh()
September 28th 2021, 09:46:42.428	PropertyCache Event lcoo_MyComp::DEFAULT::571eecc4_DEFAULT : Refreshed 0 property ClusterConstraint took 1 ms. Selective: false
September 28th 2021, 09:46:42.429	InstanceMessagesCache START: InstanceMessagesCache.refresh()
September 28th 2021, 09:46:42.433	HelixTask Message 01cb41d0-2d35-4a8f-83d4-fe662d34fff8 completed.
September 28th 2021, 09:46:42.433	HelixTask Message 01cb41d0-2d35-4a8f-83d4-fe662d34fff8 completed.
September 28th 2021, 09:46:42.437	HelixTask Delete message 01cb41d0-2d35-4a8f-83d4-fe662d34fff8 from zk!
September 28th 2021, 09:46:42.437	HelixTask Delete message 01cb41d0-2d35-4a8f-83d4-fe662d34fff8 from zk!
September 28th 2021, 09:46:42.438	CallbackHandler {} START: CallbackHandler {}, INVOKE {} listener: {} type: {}
September 28th 2021, 09:46:42.438	CallbackHandler {} START: CallbackHandler {}, INVOKE {} listener: {} type: {}
September 28th 2021, 09:46:42.438	CallbackHandler CallbackHandler {} subscribing changes listener to path: {}, callback type: {}, event types: {}, listener: {}, watchChild: {}
September 28th 2021, 09:46:42.438	CallbackHandler {} START: CallbackHandler {}, INVOKE {} listener: {} type: {}
September 28th 2021, 09:46:42.439	GenericHelixController START: GenericClusterController.onMessage() for cluster lcoo_MyComp
September 28th 2021, 09:46:42.439	GenericHelixController END: GenericClusterController.onMessage() for cluster lcoo_MyComp
September 28th 2021, 09:46:42.439	CallbackHandler CallbackHandler{}, Subscribing to path: {} took: {}
September 28th 2021, 09:46:42.440	CallbackHandler {} END:INVOKE CallbackHandler {}, {} listener: {} type: {} Took: {}ms
September 28th 2021, 09:46:42.441	InstanceMessagesCache END: InstanceMessagesCache.refresh(), {} of Messages read from ZooKeeper. took {} ms. 
September 28th 2021, 09:46:42.441	InstanceMessagesCache END: InstanceMessagesCache.refresh(), {} of Messages read from ZooKeeper. took {} ms. 
September 28th 2021, 09:46:42.442	InstanceMessagesCache Start to refresh stale message cache
September 28th 2021, 09:46:42.442	InstanceMessagesCache Start to refresh stale message cache
September 28th 2021, 09:46:42.445	MBeanRegistrar MBean {} has been registered.
September 28th 2021, 09:46:42.445	HelixTaskExecutor message finished: 01cb41d0-2d35-4a8f-83d4-fe662d34fff8, took 5179
September 28th 2021, 09:46:42.445	HelixTaskExecutor message finished: 01cb41d0-2d35-4a8f-83d4-fe662d34fff8, took 5179
September 28th 2021, 09:46:42.445	CallbackHandler CallbackHandler {} subscribing changes listener to path: {}, callback type: {}, event types: {}, listener: {}, watchChild: {}
September 28th 2021, 09:46:42.445	CallbackHandler CallbackHandler {} subscribing changes listener to path: {}, callback type: {}, event types: {}, listener: {}, watchChild: {}
September 28th 2021, 09:46:42.445	MBeanRegistrar MBean {} has been registered.
September 28th 2021, 09:46:42.446	HelixTask Message: {} (parent: {}) handling task for {}:{} completed at: {}, results: {}. FrameworkTime: {} ms; HandlerTime: {} ms.
September 28th 2021, 09:46:42.446	HelixTask Message: {} (parent: {}) handling task for {}:{} completed at: {}, results: {}. FrameworkTime: {} ms; HandlerTime: {} ms.
September 28th 2021, 09:46:42.447	CallbackHandler CallbackHandler{}, Subscribing to path: {} took: {}
September 28th 2021, 09:46:42.447	CallbackHandler CallbackHandler{}, Subscribing to path: {} took: {}
September 28th 2021, 09:46:42.448	HelixTaskExecutor No Messages to process
September 28th 2021, 09:46:42.448	CallbackHandler {} END:INVOKE CallbackHandler {}, {} listener: {} type: {} Took: {}ms
September 28th 2021, 09:46:42.448	HelixTaskExecutor No Messages to process
September 28th 2021, 09:46:42.448	CallbackHandler {} END:INVOKE CallbackHandler {}, {} listener: {} type: {} Took: {}ms
September 28th 2021, 09:46:42.457	InstanceMessagesCache END: updateRelayMessages(), {} of valid relay messages in cache, took {} ms. 
September 28th 2021, 09:46:42.457	InstanceMessagesCache END: updateRelayMessages(), {} of valid relay messages in cache, took {} ms. 
September 28th 2021, 09:46:42.457	ParticipantStateCache Event lcoo_MyComp::DEFAULT::571eecc4_DEFAULT : END: participantStateCache.refresh() for cluster lcoo_MyComp, started at : 1632815202442, took 15 ms
September 28th 2021, 09:46:42.457	ResourceControllerDataProvider Event 571eecc4_DEFAULT : No customized state config change for lcoo_MyComp cluster, DEFAULT pipeline
September 28th 2021, 09:46:42.457	AbstractDataCache Event lcoo_MyComp::TASK::571eecc4_TASK : 1 properties refreshed from ZK.
September 28th 2021, 09:46:42.457	ParticipantStateCache Event lcoo_MyComp::TASK::571eecc4_TASK : END: participantStateCache.refresh() for cluster lcoo_MyComp, started at : 1632815202442, took 15 ms
September 28th 2021, 09:46:42.458	Pipeline END CurrentStateComputationStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 571eecc4_DEFAULT
September 28th 2021, 09:46:42.458	ResourceControllerDataProvider Event 571eecc4_DEFAULT : END: ResourceControllerDataProvider.refresh() for cluster lcoo_MyComp, started at 1632815202422 took 36 for DEFAULT pipeline
September 28th 2021, 09:46:42.458	Pipeline END ResourceValidationStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 571eecc4_DEFAULT
September 28th 2021, 09:46:42.458	ParticipantStateCache Event lcoo_MyComp::DEFAULT::571eecc4_DEFAULT : END: participantStateCache.refresh() for cluster lcoo_MyComp, started at : 1632815202457, took 1 ms
September 28th 2021, 09:46:42.458	AbstractDataCache Event lcoo_MyComp::DEFAULT::571eecc4_DEFAULT : 0 properties refreshed from ZK.
September 28th 2021, 09:46:42.458	Pipeline END ResourceComputationStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 571eecc4_DEFAULT
September 28th 2021, 09:46:42.458	Pipeline END CustomizedStateComputationStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 571eecc4_DEFAULT
September 28th 2021, 09:46:42.458	Pipeline END ReadClusterDataStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 36 ms for event 571eecc4_DEFAULT
September 28th 2021, 09:46:42.459	WagedRebalancer Start calculating the new best possible assignment.
September 28th 2021, 09:46:42.459	Pipeline END ExternalViewComputeStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 571eecc4_DEFAULT
September 28th 2021, 09:46:42.459	AbstractAsyncBaseStage Submitted asynchronous {} task to worker
September 28th 2021, 09:46:42.459	Pipeline END TopStateHandoffReportStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 1 ms for event 571eecc4_DEFAULT
September 28th 2021, 09:46:42.459	WagedRebalancer Start computing new ideal states for resources: {}
September 28th 2021, 09:46:42.459	AbstractAsyncBaseStage START AsyncProcess: {}
September 28th 2021, 09:46:42.460	AbstractAsyncBaseStage END AsyncProcess: {}, took {} ms
September 28th 2021, 09:46:42.460	AbstractAsyncBaseStage Submitted asynchronous {} task to worker
September 28th 2021, 09:46:42.460	Pipeline END BestPossibleStateCalcStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 1 ms for event 571eecc4_DEFAULT
September 28th 2021, 09:46:42.460	WagedRebalancer Start calculating for an assignment with algorithm {}
September 28th 2021, 09:46:42.460	Pipeline END IntermediateStateCalcStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 571eecc4_DEFAULT
September 28th 2021, 09:46:42.460	Pipeline END MaintenanceRecoveryStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 571eecc4_DEFAULT
September 28th 2021, 09:46:42.460	AbstractAsyncBaseStage START AsyncProcess: {}
September 28th 2021, 09:46:42.460	WagedRebalancer Finish computing new ideal states for resources: {}
September 28th 2021, 09:46:42.460	WagedRebalancer Finish calculating the new best possible assignment.
September 28th 2021, 09:46:42.460	WagedRebalancer Finish calculating an assignment with algorithm {}. Took: {} ms.
September 28th 2021, 09:46:42.460	StateTransitionThrottleController No throttle config is set!
September 28th 2021, 09:46:42.461	MessageGenerationPhase Event 571eecc4_DEFAULT : Message already exists for 10.200.32.115-1037 to transit MyCompServiceResource.MyCompServiceResource_0 from ONLINE to OFFLINE, isRelay: false
September 28th 2021, 09:46:42.461	MessageGenerationPhase Event 571eecc4_DEFAULT : Adding stale message 01cb41d0-2d35-4a8f-83d4-fe662d34fff8 on instance 10.200.32.85-3376 to clean up. Msg: ONLINE->OFFLINE, current state of resource MyCompServiceResource:MyCompServiceResource_31 is ONLINE
September 28th 2021, 09:46:42.461	Pipeline END MessageSelectionStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 571eecc4_DEFAULT
September 28th 2021, 09:46:42.461	Pipeline END MessageThrottleStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 571eecc4_DEFAULT
September 28th 2021, 09:46:42.461	MessageDispatchStage Event 571eecc4_DEFAULT : Sending Message aeb4e5a4-8442-492d-bdf4-a775749a7cda to 10.200.32.85-3376 transit MyCompServiceResource.MyCompServiceResource_1|[] from:OFFLINE to:DROPPED, relayMessages: 0
September 28th 2021, 09:46:42.461	Pipeline END ResourceMessageGenerationPhase for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 571eecc4_DEFAULT
September 28th 2021, 09:46:42.467	AbstractAsyncBaseStage END AsyncProcess: {}, took {} ms
September 28th 2021, 09:46:42.470	AbstractAsyncBaseStage END AsyncProcess: {}, took {} ms
September 28th 2021, 09:46:42.470	Pipeline END TargetExteralViewCalcStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 571eecc4_DEFAULT
September 28th 2021, 09:46:42.470	MessageGenerationPhase Event 571eecc4_DEFAULT : Deleted message 01cb41d0-2d35-4a8f-83d4-fe662d34fff8 from instance 10.200.32.85-3376
September 28th 2021, 09:46:42.470	AbstractAsyncBaseStage START AsyncProcess: {}
September 28th 2021, 09:46:42.470	AbstractAsyncBaseStage END AsyncProcess: {}, took {} ms
September 28th 2021, 09:46:42.470	AbstractAsyncBaseStage START AsyncProcess: {}
September 28th 2021, 09:46:42.470	AbstractAsyncBaseStage Submitted asynchronous {} task to worker
September 28th 2021, 09:46:42.470	Pipeline END ResourceMessageDispatchStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 9 ms for event 571eecc4_DEFAULT
September 28th 2021, 09:46:42.470	AbstractAsyncBaseStage Submitted asynchronous {} task to worker
September 28th 2021, 09:46:42.470	Pipeline END PersistAssignmentStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 571eecc4_DEFAULT
September 28th 2021, 09:46:42.471	CallbackHandler {} START: CallbackHandler {}, INVOKE {} listener: {} type: {}
September 28th 2021, 09:46:42.471	GenericHelixController START: Invoking {} controller pipeline for cluster: {}. Event type: {}, ID: {}. Event session ID: {}
September 28th 2021, 09:46:42.471	GenericHelixController Controller stopping periodical rebalance timer at period 9223372036854775807
TotalProcessed time for event: CurrentStateChange took: 49 ms
InQueue time for event: CurrentStateChange took: 2 ms
September 28th 2021, 09:46:42.471	GenericHelixController Callback time for event: CurrentStateChange took: 1 ms
September 28th 2021, 09:46:42.471	GenericHelixController END: Invoking {} controller pipeline for event {}::{} for cluster {}, took {} ms
September 28th 2021, 09:46:42.471	CallbackHandler CallbackHandler {} subscribing changes listener to path: {}, callback type: {}, event types: {}, listener: {}, watchChild: {}
September 28th 2021, 09:46:42.471	BaseControllerDataProvider Event 611d6822_DEFAULT : No ideal state change for lcoo_MyComp cluster, DEFAULT pipeline
September 28th 2021, 09:46:42.471	BaseControllerDataProvider Event 611d6822_DEFAULT : No resource config change for lcoo_MyComp cluster, DEFAULT pipeline
September 28th 2021, 09:46:42.471	BaseControllerDataProvider Event 611d6822_DEFAULT : No live instance change for lcoo_MyComp cluster, DEFAULT pipeline
September 28th 2021, 09:46:42.471	BaseControllerDataProvider Event 611d6822_DEFAULT : No instance config change for lcoo_MyComp cluster, DEFAULT pipeline
September 28th 2021, 09:46:42.471	BaseControllerDataProvider Event 611d6822_DEFAULT : No ClusterConfig change for cluster lcoo_MyComp, pipeline DEFAULT
September 28th 2021, 09:46:42.472	GenericHelixController START: GenericClusterController.onMessage() for cluster lcoo_MyComp
September 28th 2021, 09:46:42.472	CallbackHandler CallbackHandler{}, Subscribing to path: {} took: {}
September 28th 2021, 09:46:42.473	CallbackHandler {} END:INVOKE CallbackHandler {}, {} listener: {} type: {} Took: {}ms
September 28th 2021, 09:46:42.473	GenericHelixController END: GenericClusterController.onMessage() for cluster lcoo_MyComp
September 28th 2021, 09:46:42.473	PropertyCache Event lcoo_MyComp::DEFAULT::611d6822_DEFAULT : Refreshed 7 property StateModelDefinition took 2 ms. Selective: false
September 28th 2021, 09:46:42.473	PropertyCache Event lcoo_MyComp::DEFAULT::611d6822_DEFAULT : Refreshed 0 property ClusterConstraint took 0 ms. Selective: false
September 28th 2021, 09:46:42.474	InstanceMessagesCache START: InstanceMessagesCache.refresh()
September 28th 2021, 09:46:42.475	CallbackHandler CallbackHandler {} subscribing changes listener to path: {}, callback type: {}, event types: {}, listener: {}, watchChild: {}
September 28th 2021, 09:46:42.475	CallbackHandler {} START: CallbackHandler {}, INVOKE {} listener: {} type: {}
September 28th 2021, 09:46:42.475	CallbackHandler CallbackHandler {} subscribing changes listener to path: {}, callback type: {}, event types: {}, listener: {}, watchChild: {}
September 28th 2021, 09:46:42.475	CallbackHandler {} START: CallbackHandler {}, INVOKE {} listener: {} type: {}
September 28th 2021, 09:46:42.476	CallbackHandler CallbackHandler{}, Subscribing to path: {} took: {}
September 28th 2021, 09:46:42.476	CallbackHandler CallbackHandler{}, Subscribing to path: {} took: {}
September 28th 2021, 09:46:42.479	AbstractDataCache Event lcoo_MyComp::TASK::571eecc4_TASK : 0 properties refreshed from ZK.
September 28th 2021, 09:46:42.479	ParticipantStateCache Event lcoo_MyComp::TASK::571eecc4_TASK : END: participantStateCache.refresh() for cluster lcoo_MyComp, started at : 1632815202458, took 21 ms
September 28th 2021, 09:46:42.479	MessageLatencyMonitor The latency of message aeb4e5a4-8442-492d-bdf4-a775749a7cda is 18 ms
September 28th 2021, 09:46:42.479	MessageLatencyMonitor The latency of message aeb4e5a4-8442-492d-bdf4-a775749a7cda is 18 ms
September 28th 2021, 09:46:42.480	Pipeline END ResourceValidationStage for TASK pipeline for cluster lcoo_MyComp. took: 0 ms for event 571eecc4_TASK
September 28th 2021, 09:46:42.480	Pipeline END CurrentStateComputationStage for TASK pipeline for cluster lcoo_MyComp. took: 0 ms for event 571eecc4_TASK
September 28th 2021, 09:46:42.480	Pipeline END ResourceComputationStage for TASK pipeline for cluster lcoo_MyComp. took: 0 ms for event 571eecc4_TASK
September 28th 2021, 09:46:42.480	Pipeline END ReadClusterDataStage for TASK pipeline for cluster lcoo_MyComp. took: 58 ms for event 571eecc4_TASK
September 28th 2021, 09:46:42.480	AssignableInstanceManager AssignableInstanceManager built AssignableInstances from scratch based on CurrentState.
September 28th 2021, 09:46:42.480	WorkflowControllerDataProvider Event 571eecc4_TASK : END: WorkflowControllerDataProvider.refresh() for cluster lcoo_MyComp, started at 1632815202422 took 58 for TASK pipeline
September 28th 2021, 09:46:42.481	GenericHelixController Controller stopping periodical rebalance timer at period 9223372036854775807
September 28th 2021, 09:46:42.481	Pipeline END TaskMessageGenerationPhase for TASK pipeline for cluster lcoo_MyComp. took: 0 ms for event 571eecc4_TASK
September 28th 2021, 09:46:42.481	Pipeline END TaskGarbageCollectionStage for TASK pipeline for cluster lcoo_MyComp. took: 0 ms for event 571eecc4_TASK
September 28th 2021, 09:46:42.481	AbstractAsyncBaseStage START AsyncProcess: {}
September 28th 2021, 09:46:42.481	Pipeline END TaskPersistDataStage for TASK pipeline for cluster lcoo_MyComp. took: 0 ms for event 571eecc4_TASK
September 28th 2021, 09:46:42.481	Pipeline END TaskSchedulingStage for TASK pipeline for cluster lcoo_MyComp. took: 1 ms for event 571eecc4_TASK
September 28th 2021, 09:46:42.481	AssignableInstanceManager Current quota capacity: {}
September 28th 2021, 09:46:42.481	Pipeline END TaskMessageDispatchStage for TASK pipeline for cluster lcoo_MyComp. took: 0 ms for event 571eecc4_TASK
September 28th 2021, 09:46:42.481	AbstractAsyncBaseStage END AsyncProcess: {}, took {} ms
September 28th 2021, 09:46:42.481	TaskPersistDataStage END TaskPersistDataStage.process() for cluster {} took {} ms
September 28th 2021, 09:46:42.481	GenericHelixController END: Invoking {} controller pipeline for event {}::{} for cluster {}, took {} ms
September 28th 2021, 09:46:42.481	AbstractAsyncBaseStage Submitted asynchronous {} task to worker
September 28th 2021, 09:46:42.481	TaskPersistDataStage START TaskPersistDataStage.process()
September 28th 2021, 09:46:42.482	BaseControllerDataProvider Event d183655f_TASK : No live instance change for lcoo_MyComp cluster, TASK pipeline
September 28th 2021, 09:46:42.482	BaseControllerDataProvider Event d183655f_TASK : No instance config change for lcoo_MyComp cluster, TASK pipeline
September 28th 2021, 09:46:42.482	BaseControllerDataProvider Event d183655f_TASK : No resource config change for lcoo_MyComp cluster, TASK pipeline
September 28th 2021, 09:46:42.482	BaseControllerDataProvider Event d183655f_TASK : No ideal state change for lcoo_MyComp cluster, TASK pipeline
September 28th 2021, 09:46:42.482	BaseControllerDataProvider Event d183655f_TASK : No ClusterConfig change for cluster lcoo_MyComp, pipeline TASK
September 28th 2021, 09:46:42.482	GenericHelixController START: Invoking {} controller pipeline for cluster: {}. Event type: {}, ID: {}. Event session ID: {}
September 28th 2021, 09:46:42.483	PropertyCache Event lcoo_MyComp::TASK::d183655f_TASK : Refreshed 0 property ClusterConstraint took 0 ms. Selective: false
September 28th 2021, 09:46:42.483	PropertyCache Event lcoo_MyComp::TASK::d183655f_TASK : Refreshed 7 property StateModelDefinition took 1 ms. Selective: false
September 28th 2021, 09:46:42.484	InstanceMessagesCache START: InstanceMessagesCache.refresh()
September 28th 2021, 09:46:42.486	InstanceMessagesCache END: InstanceMessagesCache.refresh(), {} of Messages read from ZooKeeper. took {} ms. 
September 28th 2021, 09:46:42.486	InstanceMessagesCache Start to refresh stale message cache
September 28th 2021, 09:46:42.492	InstanceMessagesCache END: InstanceMessagesCache.refresh(), {} of Messages read from ZooKeeper. took {} ms. 
September 28th 2021, 09:46:42.493	InstanceMessagesCache Start to refresh stale message cache
September 28th 2021, 09:46:42.498	ParticipantStateCache Event lcoo_MyComp::DEFAULT::611d6822_DEFAULT : END: participantStateCache.refresh() for cluster lcoo_MyComp, started at : 1632815202487, took 11 ms
September 28th 2021, 09:46:42.498	AbstractDataCache Event lcoo_MyComp::DEFAULT::611d6822_DEFAULT : 0 properties refreshed from ZK.
September 28th 2021, 09:46:42.499	Pipeline END ReadClusterDataStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 28 ms for event 611d6822_DEFAULT
September 28th 2021, 09:46:42.499	AbstractDataCache Event lcoo_MyComp::DEFAULT::611d6822_DEFAULT : 0 properties refreshed from ZK.
September 28th 2021, 09:46:42.499	ResourceControllerDataProvider Event 611d6822_DEFAULT : No customized state config change for lcoo_MyComp cluster, DEFAULT pipeline
September 28th 2021, 09:46:42.499	InstanceMessagesCache END: updateRelayMessages(), {} of valid relay messages in cache, took {} ms. 
September 28th 2021, 09:46:42.499	ResourceControllerDataProvider Event 611d6822_DEFAULT : END: ResourceControllerDataProvider.refresh() for cluster lcoo_MyComp, started at 1632815202471 took 28 for DEFAULT pipeline
September 28th 2021, 09:46:42.499	ParticipantStateCache Event lcoo_MyComp::DEFAULT::611d6822_DEFAULT : END: participantStateCache.refresh() for cluster lcoo_MyComp, started at : 1632815202499, took 0 ms
September 28th 2021, 09:46:42.499	Pipeline END ResourceValidationStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 611d6822_DEFAULT
September 28th 2021, 09:46:42.499	Pipeline END ResourceComputationStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 611d6822_DEFAULT
September 28th 2021, 09:46:42.500	Pipeline END TopStateHandoffReportStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 611d6822_DEFAULT
September 28th 2021, 09:46:42.500	WagedRebalancer Start computing new ideal states for resources: {}
September 28th 2021, 09:46:42.500	Pipeline END CustomizedStateComputationStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 611d6822_DEFAULT
September 28th 2021, 09:46:42.500	Pipeline END CurrentStateComputationStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 611d6822_DEFAULT
September 28th 2021, 09:46:42.501	WagedRebalancer Start calculating for an assignment with algorithm {}
September 28th 2021, 09:46:42.501	WagedRebalancer Start calculating the new best possible assignment.
September 28th 2021, 09:46:42.502	WagedRebalancer Finish computing new ideal states for resources: {}
September 28th 2021, 09:46:42.502	WagedRebalancer Finish calculating an assignment with algorithm {}. Took: {} ms.
September 28th 2021, 09:46:42.502	WagedRebalancer Finish calculating the new best possible assignment.
September 28th 2021, 09:46:42.503	StateTransitionThrottleController No throttle config is set!
September 28th 2021, 09:46:42.503	Pipeline END BestPossibleStateCalcStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 3 ms for event 611d6822_DEFAULT
September 28th 2021, 09:46:42.504	MessageGenerationPhase Event 611d6822_DEFAULT : Message already exists for 10.200.32.115-1037 to transit MyCompServiceResource.MyCompServiceResource_0 from ONLINE to OFFLINE, isRelay: false
September 28th 2021, 09:46:42.504	AbstractAsyncBaseStage END AsyncProcess: {}, took {} ms
September 28th 2021, 09:46:42.504	AbstractAsyncBaseStage START AsyncProcess: {}
September 28th 2021, 09:46:42.504	AbstractAsyncBaseStage Submitted asynchronous {} task to worker
September 28th 2021, 09:46:42.504	Pipeline END MaintenanceRecoveryStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 611d6822_DEFAULT
September 28th 2021, 09:46:42.504	Pipeline END IntermediateStateCalcStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 1 ms for event 611d6822_DEFAULT
September 28th 2021, 09:46:42.505	Pipeline END MessageThrottleStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 611d6822_DEFAULT
September 28th 2021, 09:46:42.505	AbstractAsyncBaseStage START AsyncProcess: {}
September 28th 2021, 09:46:42.505	MessageGenerationPhase Event 611d6822_DEFAULT : Message already exists for 10.200.32.85-3376 to transit MyCompServiceResource.MyCompServiceResource_1 from OFFLINE to DROPPED, isRelay: false
September 28th 2021, 09:46:42.505	AbstractAsyncBaseStage Submitted asynchronous {} task to worker
September 28th 2021, 09:46:42.505	Pipeline END MessageSelectionStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 611d6822_DEFAULT
September 28th 2021, 09:46:42.505	Pipeline END ResourceMessageGenerationPhase for DEFAULT pipeline for cluster lcoo_MyComp. took: 1 ms for event 611d6822_DEFAULT
September 28th 2021, 09:46:42.505	Pipeline END PersistAssignmentStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 611d6822_DEFAULT
September 28th 2021, 09:46:42.505	AbstractDataCache Event lcoo_MyComp::TASK::d183655f_TASK : 0 properties refreshed from ZK.
September 28th 2021, 09:46:42.505	Pipeline END ResourceMessageDispatchStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 611d6822_DEFAULT
September 28th 2021, 09:46:42.506	GenericHelixController Controller stopping periodical rebalance timer at period 9223372036854775807
TotalProcessed time for event: MessageChange took: 35 ms
InQueue time for event: MessageChange took: 32 ms
September 28th 2021, 09:46:42.506	GenericHelixController Callback time for event: MessageChange took: 1 ms
September 28th 2021, 09:46:42.506	Pipeline END TargetExteralViewCalcStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 611d6822_DEFAULT
September 28th 2021, 09:46:42.506	AbstractAsyncBaseStage Submitted asynchronous {} task to worker
September 28th 2021, 09:46:42.506	AbstractAsyncBaseStage START AsyncProcess: {}
September 28th 2021, 09:46:42.506	AbstractAsyncBaseStage END AsyncProcess: {}, took {} ms
September 28th 2021, 09:46:42.506	GenericHelixController END: Invoking {} controller pipeline for event {}::{} for cluster {}, took {} ms
September 28th 2021, 09:46:42.506	AbstractAsyncBaseStage END AsyncProcess: {}, took {} ms
September 28th 2021, 09:46:42.506	GenericHelixController START: Invoking {} controller pipeline for cluster: {}. Event type: {}, ID: {}. Event session ID: {}
September 28th 2021, 09:46:42.506	InstanceMessagesCache END: updateRelayMessages(), {} of valid relay messages in cache, took {} ms. 
September 28th 2021, 09:46:42.506	ParticipantStateCache Event lcoo_MyComp::TASK::d183655f_TASK : END: participantStateCache.refresh() for cluster lcoo_MyComp, started at : 1632815202493, took 13 ms
September 28th 2021, 09:46:42.507	BaseControllerDataProvider Event d183655f_DEFAULT : No ideal state change for lcoo_MyComp cluster, DEFAULT pipeline
September 28th 2021, 09:46:42.507	BaseControllerDataProvider Event d183655f_DEFAULT : No instance config change for lcoo_MyComp cluster, DEFAULT pipeline
September 28th 2021, 09:46:42.507	BaseControllerDataProvider Event d183655f_DEFAULT : No live instance change for lcoo_MyComp cluster, DEFAULT pipeline
September 28th 2021, 09:46:42.507	BaseControllerDataProvider Event d183655f_DEFAULT : No ClusterConfig change for cluster lcoo_MyComp, pipeline DEFAULT
September 28th 2021, 09:46:42.507	BaseControllerDataProvider Event d183655f_DEFAULT : No resource config change for lcoo_MyComp cluster, DEFAULT pipeline
September 28th 2021, 09:46:42.508	PropertyCache Event lcoo_MyComp::DEFAULT::d183655f_DEFAULT : Refreshed 7 property StateModelDefinition took 1 ms. Selective: false
September 28th 2021, 09:46:42.508	PropertyCache Event lcoo_MyComp::DEFAULT::d183655f_DEFAULT : Refreshed 0 property ClusterConstraint took 0 ms. Selective: false
September 28th 2021, 09:46:42.509	InstanceMessagesCache START: InstanceMessagesCache.refresh()
September 28th 2021, 09:46:42.513	HelixTaskExecutor Scheduling message {}: {}:{}, {}->{}
September 28th 2021, 09:46:42.513	HelixTaskExecutor Scheduling message {}: {}:{}, {}->{}
September 28th 2021, 09:46:42.517	Pipeline END CurrentStateComputationStage for TASK pipeline for cluster lcoo_MyComp. took: 0 ms for event d183655f_TASK
September 28th 2021, 09:46:42.517	WorkflowControllerDataProvider Event d183655f_TASK : END: WorkflowControllerDataProvider.refresh() for cluster lcoo_MyComp, started at 1632815202482 took 35 for TASK pipeline
September 28th 2021, 09:46:42.517	AbstractDataCache Event lcoo_MyComp::TASK::d183655f_TASK : 0 properties refreshed from ZK.
September 28th 2021, 09:46:42.517	Pipeline END ResourceValidationStage for TASK pipeline for cluster lcoo_MyComp. took: 0 ms for event d183655f_TASK
September 28th 2021, 09:46:42.517	Pipeline END ResourceComputationStage for TASK pipeline for cluster lcoo_MyComp. took: 0 ms for event d183655f_TASK
September 28th 2021, 09:46:42.517	ParticipantStateCache Event lcoo_MyComp::TASK::d183655f_TASK : END: participantStateCache.refresh() for cluster lcoo_MyComp, started at : 1632815202506, took 11 ms
September 28th 2021, 09:46:42.517	Pipeline END ReadClusterDataStage for TASK pipeline for cluster lcoo_MyComp. took: 35 ms for event d183655f_TASK
September 28th 2021, 09:46:42.518	GenericHelixController END: Invoking {} controller pipeline for event {}::{} for cluster {}, took {} ms
September 28th 2021, 09:46:42.518	TaskPersistDataStage START TaskPersistDataStage.process()
September 28th 2021, 09:46:42.518	AssignableInstanceManager Current quota capacity: {}
September 28th 2021, 09:46:42.518	AssignableInstanceManager AssignableInstanceManager built AssignableInstances from scratch based on CurrentState.
September 28th 2021, 09:46:42.518	Pipeline END TaskMessageDispatchStage for TASK pipeline for cluster lcoo_MyComp. took: 0 ms for event d183655f_TASK
September 28th 2021, 09:46:42.518	Pipeline END TaskPersistDataStage for TASK pipeline for cluster lcoo_MyComp. took: 0 ms for event d183655f_TASK
September 28th 2021, 09:46:42.518	TaskPersistDataStage END TaskPersistDataStage.process() for cluster {} took {} ms
September 28th 2021, 09:46:42.518	Pipeline END TaskSchedulingStage for TASK pipeline for cluster lcoo_MyComp. took: 0 ms for event d183655f_TASK
September 28th 2021, 09:46:42.518	AbstractAsyncBaseStage END AsyncProcess: {}, took {} ms
September 28th 2021, 09:46:42.518	Pipeline END TaskMessageGenerationPhase for TASK pipeline for cluster lcoo_MyComp. took: 0 ms for event d183655f_TASK
September 28th 2021, 09:46:42.518	AbstractAsyncBaseStage START AsyncProcess: {}
September 28th 2021, 09:46:42.518	Pipeline END TaskGarbageCollectionStage for TASK pipeline for cluster lcoo_MyComp. took: 0 ms for event d183655f_TASK
September 28th 2021, 09:46:42.518	AbstractAsyncBaseStage Submitted asynchronous {} task to worker
September 28th 2021, 09:46:42.520	InstanceMessagesCache END: InstanceMessagesCache.refresh(), {} of Messages read from ZooKeeper. took {} ms. 
September 28th 2021, 09:46:42.521	InstanceMessagesCache Start to refresh stale message cache
September 28th 2021, 09:46:42.527	HelixTask handling task: aeb4e5a4-8442-492d-bdf4-a775749a7cda begin, at: 1632815202527
September 28th 2021, 09:46:42.527	HelixTaskExecutor Message: aeb4e5a4-8442-492d-bdf4-a775749a7cda handling task scheduled
September 28th 2021, 09:46:42.527	HelixTaskExecutor Submit task: aeb4e5a4-8442-492d-bdf4-a775749a7cda to pool: java.util.concurrent.ThreadPoolExecutor@3fe6ce3[Running, pool size = 3, active threads = 0, queued tasks = 0, completed tasks = 3]
September 28th 2021, 09:46:42.527	HelixTaskExecutor Submit task: aeb4e5a4-8442-492d-bdf4-a775749a7cda to pool: java.util.concurrent.ThreadPoolExecutor@3fe6ce3[Running, pool size = 3, active threads = 0, queued tasks = 0, completed tasks = 3]
September 28th 2021, 09:46:42.527	HelixTask handling task: aeb4e5a4-8442-492d-bdf4-a775749a7cda begin, at: 1632815202527
September 28th 2021, 09:46:42.527	HelixTaskExecutor Message: aeb4e5a4-8442-492d-bdf4-a775749a7cda handling task scheduled
September 28th 2021, 09:46:42.528	CallbackHandler {} END:INVOKE CallbackHandler {}, {} listener: {} type: {} Took: {}ms
September 28th 2021, 09:46:42.528	CallbackHandler {} END:INVOKE CallbackHandler {}, {} listener: {} type: {} Took: {}ms
September 28th 2021, 09:46:42.563	AbstractDataCache Event lcoo_MyComp::DEFAULT::d183655f_DEFAULT : 0 properties refreshed from ZK.
September 28th 2021, 09:46:42.564	ParticipantStateCache Event lcoo_MyComp::DEFAULT::d183655f_DEFAULT : END: participantStateCache.refresh() for cluster lcoo_MyComp, started at : 1632815202564, took 0 ms
September 28th 2021, 09:46:42.564	Pipeline END ReadClusterDataStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 57 ms for event d183655f_DEFAULT
September 28th 2021, 09:46:42.564	InstanceMessagesCache END: updateRelayMessages(), {} of valid relay messages in cache, took {} ms. 
September 28th 2021, 09:46:42.564	ParticipantStateCache Event lcoo_MyComp::DEFAULT::d183655f_DEFAULT : END: participantStateCache.refresh() for cluster lcoo_MyComp, started at : 1632815202521, took 43 ms
September 28th 2021, 09:46:42.564	ResourceControllerDataProvider Event d183655f_DEFAULT : END: ResourceControllerDataProvider.refresh() for cluster lcoo_MyComp, started at 1632815202507 took 57 for DEFAULT pipeline
September 28th 2021, 09:46:42.564	ResourceControllerDataProvider Event d183655f_DEFAULT : No customized state config change for lcoo_MyComp cluster, DEFAULT pipeline
September 28th 2021, 09:46:42.564	AbstractDataCache Event lcoo_MyComp::DEFAULT::d183655f_DEFAULT : 0 properties refreshed from ZK.
September 28th 2021, 09:46:42.565	Pipeline END CustomizedStateComputationStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event d183655f_DEFAULT
September 28th 2021, 09:46:42.565	Pipeline END ResourceValidationStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event d183655f_DEFAULT
September 28th 2021, 09:46:42.565	Pipeline END ResourceComputationStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event d183655f_DEFAULT
September 28th 2021, 09:46:42.565	Pipeline END CurrentStateComputationStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event d183655f_DEFAULT
September 28th 2021, 09:46:42.566	Pipeline END TopStateHandoffReportStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 1 ms for event d183655f_DEFAULT
September 28th 2021, 09:46:42.566	WagedRebalancer Start calculating the new best possible assignment.
September 28th 2021, 09:46:42.566	WagedRebalancer Start computing new ideal states for resources: {}
September 28th 2021, 09:46:42.567	WagedRebalancer Finish computing new ideal states for resources: {}
September 28th 2021, 09:46:42.567	WagedRebalancer Start calculating for an assignment with algorithm {}
September 28th 2021, 09:46:42.567	WagedRebalancer Finish calculating the new best possible assignment.
September 28th 2021, 09:46:42.567	WagedRebalancer Finish calculating an assignment with algorithm {}. Took: {} ms.
September 28th 2021, 09:46:42.568	Pipeline END MaintenanceRecoveryStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event d183655f_DEFAULT
September 28th 2021, 09:46:42.568	AbstractAsyncBaseStage Submitted asynchronous {} task to worker
September 28th 2021, 09:46:42.568	StateTransitionThrottleController No throttle config is set!
September 28th 2021, 09:46:42.568	Pipeline END BestPossibleStateCalcStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 2 ms for event d183655f_DEFAULT
September 28th 2021, 09:46:42.568	AbstractAsyncBaseStage END AsyncProcess: {}, took {} ms
September 28th 2021, 09:46:42.568	Pipeline END IntermediateStateCalcStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event d183655f_DEFAULT
September 28th 2021, 09:46:42.568	MessageGenerationPhase Event d183655f_DEFAULT : Message already exists for 10.200.32.115-1037 to transit MyCompServiceResource.MyCompServiceResource_0 from ONLINE to OFFLINE, isRelay: false
September 28th 2021, 09:46:42.568	AbstractAsyncBaseStage START AsyncProcess: {}
September 28th 2021, 09:46:42.569	AbstractAsyncBaseStage END AsyncProcess: {}, took {} ms
TotalProcessed time for event: MessageChange took: 62 ms
InQueue time for event: MessageChange took: 35 ms
September 28th 2021, 09:46:42.569	GenericHelixController Callback time for event: MessageChange took: 1 ms
September 28th 2021, 09:46:42.569	AbstractAsyncBaseStage START AsyncProcess: {}
September 28th 2021, 09:46:42.569	AbstractAsyncBaseStage Submitted asynchronous {} task to worker
September 28th 2021, 09:46:42.569	GenericHelixController END: Invoking {} controller pipeline for event {}::{} for cluster {}, took {} ms
September 28th 2021, 09:46:42.569	Pipeline END TargetExteralViewCalcStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event d183655f_DEFAULT
September 28th 2021, 09:46:42.569	Pipeline END PersistAssignmentStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event d183655f_DEFAULT
September 28th 2021, 09:46:42.569	Pipeline END MessageThrottleStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event d183655f_DEFAULT
September 28th 2021, 09:46:42.569	MessageGenerationPhase Event d183655f_DEFAULT : Message already exists for 10.200.32.85-3376 to transit MyCompServiceResource.MyCompServiceResource_1 from OFFLINE to DROPPED, isRelay: false
September 28th 2021, 09:46:42.569	Pipeline END ResourceMessageDispatchStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event d183655f_DEFAULT
September 28th 2021, 09:46:42.569	Pipeline END MessageSelectionStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event d183655f_DEFAULT
September 28th 2021, 09:46:42.569	AbstractAsyncBaseStage END AsyncProcess: {}, took {} ms
September 28th 2021, 09:46:42.569	AbstractAsyncBaseStage START AsyncProcess: {}
September 28th 2021, 09:46:42.569	AbstractAsyncBaseStage Submitted asynchronous {} task to worker
September 28th 2021, 09:46:42.569	Pipeline END ResourceMessageGenerationPhase for DEFAULT pipeline for cluster lcoo_MyComp. took: 1 ms for event d183655f_DEFAULT
September 28th 2021, 09:46:42.606	HelixStateTransitionHandler handling message: aeb4e5a4-8442-492d-bdf4-a775749a7cda transit MyCompServiceResource.MyCompServiceResource_1|[] from:OFFLINE to:DROPPED, relayedFrom: null
September 28th 2021, 09:46:42.606	HelixStateTransitionHandler handling message: aeb4e5a4-8442-492d-bdf4-a775749a7cda transit MyCompServiceResource.MyCompServiceResource_1|[] from:OFFLINE to:DROPPED, relayedFrom: null
September 28th 2021, 09:46:42.608	ZNRecord Merging with delta list, recordId = MyCompServiceResource other:MyCompServiceResource
September 28th 2021, 09:46:42.608	ZNRecord Merging with delta list, recordId = MyCompServiceResource other:MyCompServiceResource
September 28th 2021, 09:46:42.614	GenericHelixController START: GenericClusterController.onStateChange()
September 28th 2021, 09:46:42.614	CallbackHandler {} START: CallbackHandler {}, INVOKE {} listener: {} type: {}
September 28th 2021, 09:46:42.615	GenericHelixController START: Invoking {} controller pipeline for cluster: {}. Event type: {}, ID: {}. Event session ID: {}
September 28th 2021, 09:46:42.615	BaseControllerDataProvider Event 9375e6b8_DEFAULT : No ideal state change for lcoo_MyComp cluster, DEFAULT pipeline
September 28th 2021, 09:46:42.615	CallbackHandler {} END:INVOKE CallbackHandler {}, {} listener: {} type: {} Took: {}ms
September 28th 2021, 09:46:42.615	BaseControllerDataProvider Event 9375e6b8_DEFAULT : No ClusterConfig change for cluster lcoo_MyComp, pipeline DEFAULT
September 28th 2021, 09:46:42.615	GenericHelixController Controller stopping periodical rebalance timer at period 9223372036854775807
September 28th 2021, 09:46:42.615	GenericHelixController END: GenericClusterController.onStateChange()
September 28th 2021, 09:46:42.615	GenericHelixController START: Invoking {} controller pipeline for cluster: {}. Event type: {}, ID: {}. Event session ID: {}
September 28th 2021, 09:46:42.615	GenericHelixController Controller stopping periodical rebalance timer at period 9223372036854775807
September 28th 2021, 09:46:42.616	BaseControllerDataProvider Event 9375e6b8_TASK : No ideal state change for lcoo_MyComp cluster, TASK pipeline
September 28th 2021, 09:46:42.616	BaseControllerDataProvider Event 9375e6b8_DEFAULT : No instance config change for lcoo_MyComp cluster, DEFAULT pipeline
September 28th 2021, 09:46:42.616	BaseControllerDataProvider Event 9375e6b8_DEFAULT : No live instance change for lcoo_MyComp cluster, DEFAULT pipeline
September 28th 2021, 09:46:42.616	BaseControllerDataProvider Event 9375e6b8_DEFAULT : No resource config change for lcoo_MyComp cluster, DEFAULT pipeline
September 28th 2021, 09:46:42.616	BaseControllerDataProvider Event 9375e6b8_TASK : No ClusterConfig change for cluster lcoo_MyComp, pipeline TASK
September 28th 2021, 09:46:42.617	BaseControllerDataProvider Event 9375e6b8_TASK : No resource config change for lcoo_MyComp cluster, TASK pipeline
September 28th 2021, 09:46:42.617	BaseControllerDataProvider Event 9375e6b8_TASK : No instance config change for lcoo_MyComp cluster, TASK pipeline
September 28th 2021, 09:46:42.617	BaseControllerDataProvider Event 9375e6b8_TASK : No live instance change for lcoo_MyComp cluster, TASK pipeline
September 28th 2021, 09:46:42.619	PropertyCache Event lcoo_MyComp::TASK::9375e6b8_TASK : Refreshed 7 property StateModelDefinition took 2 ms. Selective: false
September 28th 2021, 09:46:42.620	InstanceMessagesCache START: InstanceMessagesCache.refresh()
September 28th 2021, 09:46:42.620	PropertyCache Event lcoo_MyComp::DEFAULT::9375e6b8_DEFAULT : Refreshed 7 property StateModelDefinition took 3 ms. Selective: false
September 28th 2021, 09:46:42.620	PropertyCache Event lcoo_MyComp::TASK::9375e6b8_TASK : Refreshed 0 property ClusterConstraint took 1 ms. Selective: false
September 28th 2021, 09:46:42.621	InstanceMessagesCache START: InstanceMessagesCache.refresh()
September 28th 2021, 09:46:42.621	PropertyCache Event lcoo_MyComp::DEFAULT::9375e6b8_DEFAULT : Refreshed 0 property ClusterConstraint took 0 ms. Selective: false
September 28th 2021, 09:46:42.628	OnlineOfflineStateModel Transitioning partition MyCompServiceResource_1 from OFFLINE to DROPPED state
September 28th 2021, 09:46:42.628	HelixStateTransitionHandler Instance 10.200.32.85-3376, partition MyCompServiceResource_1 received state transition from OFFLINE to DROPPED on session 279ef46108f009f, message id: aeb4e5a4-8442-492d-bdf4-a775749a7cda
September 28th 2021, 09:46:42.628	OnlineOfflineStateModel Transitioning partition MyCompServiceResource_1 from OFFLINE to DROPPED state
September 28th 2021, 09:46:42.628	HelixStateTransitionHandler Instance 10.200.32.85-3376, partition MyCompServiceResource_1 received state transition from OFFLINE to DROPPED on session 279ef46108f009f, message id: aeb4e5a4-8442-492d-bdf4-a775749a7cda
September 28th 2021, 09:46:42.630	ZNRecord Merging with delta list, recordId = MyCompServiceResource other:MyCompServiceResource
September 28th 2021, 09:46:42.630	ZNRecord Merging with delta list, recordId = MyCompServiceResource other:MyCompServiceResource
September 28th 2021, 09:46:42.635	InstanceMessagesCache Start to refresh stale message cache
September 28th 2021, 09:46:42.635	InstanceMessagesCache END: InstanceMessagesCache.refresh(), {} of Messages read from ZooKeeper. took {} ms. 
September 28th 2021, 09:46:42.636	InstanceMessagesCache END: InstanceMessagesCache.refresh(), {} of Messages read from ZooKeeper. took {} ms. 
September 28th 2021, 09:46:42.636	GenericHelixController START: GenericClusterController.onStateChange()
September 28th 2021, 09:46:42.636	CallbackHandler {} START: CallbackHandler {}, INVOKE {} listener: {} type: {}
September 28th 2021, 09:46:42.636	InstanceMessagesCache Start to refresh stale message cache
September 28th 2021, 09:46:42.637	GenericHelixController END: GenericClusterController.onStateChange()
September 28th 2021, 09:46:42.637	CallbackHandler {} END:INVOKE CallbackHandler {}, {} listener: {} type: {} Took: {}ms
September 28th 2021, 09:46:42.648	ParticipantStateCache Event lcoo_MyComp::TASK::9375e6b8_TASK : END: participantStateCache.refresh() for cluster lcoo_MyComp, started at : 1632815202635, took 13 ms
September 28th 2021, 09:46:42.648	AbstractDataCache Event lcoo_MyComp::TASK::9375e6b8_TASK : 1 properties refreshed from ZK.
September 28th 2021, 09:46:42.648	InstanceMessagesCache END: updateRelayMessages(), {} of valid relay messages in cache, took {} ms. 
September 28th 2021, 09:46:42.649	HelixTask Message aeb4e5a4-8442-492d-bdf4-a775749a7cda completed.
September 28th 2021, 09:46:42.649	HelixTask Message aeb4e5a4-8442-492d-bdf4-a775749a7cda completed.
September 28th 2021, 09:46:42.652	AbstractDataCache Event lcoo_MyComp::DEFAULT::9375e6b8_DEFAULT : 1 properties refreshed from ZK.
September 28th 2021, 09:46:42.652	ParticipantStateCache Event lcoo_MyComp::DEFAULT::9375e6b8_DEFAULT : END: participantStateCache.refresh() for cluster lcoo_MyComp, started at : 1632815202636, took 16 ms
September 28th 2021, 09:46:42.653	Pipeline END ResourceComputationStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 9375e6b8_DEFAULT
September 28th 2021, 09:46:42.653	ParticipantStateCache Event lcoo_MyComp::DEFAULT::9375e6b8_DEFAULT : END: participantStateCache.refresh() for cluster lcoo_MyComp, started at : 1632815202653, took 0 ms
September 28th 2021, 09:46:42.653	InstanceMessagesCache END: updateRelayMessages(), {} of valid relay messages in cache, took {} ms. 
September 28th 2021, 09:46:42.653	ResourceControllerDataProvider Event 9375e6b8_DEFAULT : No customized state config change for lcoo_MyComp cluster, DEFAULT pipeline
September 28th 2021, 09:46:42.653	Pipeline END ResourceValidationStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 9375e6b8_DEFAULT
September 28th 2021, 09:46:42.653	Pipeline END ReadClusterDataStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 38 ms for event 9375e6b8_DEFAULT
September 28th 2021, 09:46:42.653	ResourceControllerDataProvider Event 9375e6b8_DEFAULT : END: ResourceControllerDataProvider.refresh() for cluster lcoo_MyComp, started at 1632815202615 took 38 for DEFAULT pipeline
September 28th 2021, 09:46:42.653	AbstractDataCache Event lcoo_MyComp::DEFAULT::9375e6b8_DEFAULT : 0 properties refreshed from ZK.
September 28th 2021, 09:46:42.654	Pipeline END TopStateHandoffReportStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 9375e6b8_DEFAULT
September 28th 2021, 09:46:42.654	MBeanRegistrar MBean {} has been registered.
September 28th 2021, 09:46:42.654	HelixTask Delete message aeb4e5a4-8442-492d-bdf4-a775749a7cda from zk!
September 28th 2021, 09:46:42.654	HelixTask Delete message aeb4e5a4-8442-492d-bdf4-a775749a7cda from zk!
September 28th 2021, 09:46:42.654	Pipeline END ExternalViewComputeStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 9375e6b8_DEFAULT
September 28th 2021, 09:46:42.654	Pipeline END CustomizedStateComputationStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 9375e6b8_DEFAULT
September 28th 2021, 09:46:42.654	Pipeline END CurrentStateComputationStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 9375e6b8_DEFAULT
September 28th 2021, 09:46:42.654	AbstractAsyncBaseStage START AsyncProcess: {}
September 28th 2021, 09:46:42.654	AbstractAsyncBaseStage Submitted asynchronous {} task to worker
September 28th 2021, 09:46:42.654	MBeanRegistrar MBean {} has been registered.
September 28th 2021, 09:46:42.655	WagedRebalancer Start calculating for an assignment with algorithm {}
September 28th 2021, 09:46:42.655	WagedRebalancer Start computing new ideal states for resources: {}
September 28th 2021, 09:46:42.655	WagedRebalancer Start calculating the new best possible assignment.
September 28th 2021, 09:46:42.656	Pipeline END BestPossibleStateCalcStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 1 ms for event 9375e6b8_DEFAULT
September 28th 2021, 09:46:42.656	WagedRebalancer Finish computing new ideal states for resources: {}
September 28th 2021, 09:46:42.656	WagedRebalancer Finish calculating an assignment with algorithm {}. Took: {} ms.
September 28th 2021, 09:46:42.656	WagedRebalancer Finish calculating the new best possible assignment.
September 28th 2021, 09:46:42.657	Pipeline END MaintenanceRecoveryStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 9375e6b8_DEFAULT
September 28th 2021, 09:46:42.657	AbstractAsyncBaseStage START AsyncProcess: {}
September 28th 2021, 09:46:42.657	Pipeline END IntermediateStateCalcStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 9375e6b8_DEFAULT
September 28th 2021, 09:46:42.657	HelixTask Message: {} (parent: {}) handling task for {}:{} completed at: {}, results: {}. FrameworkTime: {} ms; HandlerTime: {} ms.
September 28th 2021, 09:46:42.657	StateTransitionThrottleController No throttle config is set!
September 28th 2021, 09:46:42.657	HelixTaskExecutor message finished: aeb4e5a4-8442-492d-bdf4-a775749a7cda, took 50
September 28th 2021, 09:46:42.657	HelixTask Message: {} (parent: {}) handling task for {}:{} completed at: {}, results: {}. FrameworkTime: {} ms; HandlerTime: {} ms.
September 28th 2021, 09:46:42.657	MessageGenerationPhase Event 9375e6b8_DEFAULT : Message already exists for 10.200.32.115-1037 to transit MyCompServiceResource.MyCompServiceResource_0 from ONLINE to OFFLINE, isRelay: false
September 28th 2021, 09:46:42.657	AbstractAsyncBaseStage END AsyncProcess: {}, took {} ms
September 28th 2021, 09:46:42.657	AbstractAsyncBaseStage Submitted asynchronous {} task to worker
September 28th 2021, 09:46:42.657	Pipeline END ResourceMessageGenerationPhase for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 9375e6b8_DEFAULT
September 28th 2021, 09:46:42.657	MessageGenerationPhase Event 9375e6b8_DEFAULT : Message already exists for 10.200.32.85-3376 to transit MyCompServiceResource.MyCompServiceResource_1 from OFFLINE to DROPPED, isRelay: false
September 28th 2021, 09:46:42.657	HelixTaskExecutor message finished: aeb4e5a4-8442-492d-bdf4-a775749a7cda, took 50
September 28th 2021, 09:46:42.658	AbstractAsyncBaseStage START AsyncProcess: {}
September 28th 2021, 09:46:42.658	AbstractAsyncBaseStage Submitted asynchronous {} task to worker
TotalProcessed time for event: CurrentStateChange took: 43 ms
InQueue time for event: CurrentStateChange took: 1 ms
September 28th 2021, 09:46:42.658	GenericHelixController Callback time for event: CurrentStateChange took: 0 ms
September 28th 2021, 09:46:42.658	AbstractAsyncBaseStage Submitted asynchronous {} task to worker
September 28th 2021, 09:46:42.658	GenericHelixController Controller stopping periodical rebalance timer at period 9223372036854775807
September 28th 2021, 09:46:42.658	GenericHelixController END: Invoking {} controller pipeline for event {}::{} for cluster {}, took {} ms
September 28th 2021, 09:46:42.658	Pipeline END TargetExteralViewCalcStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 9375e6b8_DEFAULT
September 28th 2021, 09:46:42.658	Pipeline END ResourceMessageDispatchStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 9375e6b8_DEFAULT
September 28th 2021, 09:46:42.658	AbstractAsyncBaseStage END AsyncProcess: {}, took {} ms
September 28th 2021, 09:46:42.658	Pipeline END MessageThrottleStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 9375e6b8_DEFAULT
September 28th 2021, 09:46:42.658	Pipeline END PersistAssignmentStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 9375e6b8_DEFAULT
September 28th 2021, 09:46:42.658	AbstractAsyncBaseStage START AsyncProcess: {}
September 28th 2021, 09:46:42.658	Pipeline END MessageSelectionStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 9375e6b8_DEFAULT
September 28th 2021, 09:46:42.659	BaseControllerDataProvider Event cf855014_DEFAULT : No resource config change for lcoo_MyComp cluster, DEFAULT pipeline
September 28th 2021, 09:46:42.659	BaseControllerDataProvider Event cf855014_DEFAULT : No ideal state change for lcoo_MyComp cluster, DEFAULT pipeline
September 28th 2021, 09:46:42.659	BaseControllerDataProvider Event cf855014_DEFAULT : No ClusterConfig change for cluster lcoo_MyComp, pipeline DEFAULT
September 28th 2021, 09:46:42.659	BaseControllerDataProvider Event cf855014_DEFAULT : No live instance change for lcoo_MyComp cluster, DEFAULT pipeline
September 28th 2021, 09:46:42.659	BaseControllerDataProvider Event cf855014_DEFAULT : No instance config change for lcoo_MyComp cluster, DEFAULT pipeline
September 28th 2021, 09:46:42.659	AbstractAsyncBaseStage END AsyncProcess: {}, took {} ms
September 28th 2021, 09:46:42.659	GenericHelixController START: Invoking {} controller pipeline for cluster: {}. Event type: {}, ID: {}. Event session ID: {}
September 28th 2021, 09:46:42.665	CallbackHandler CallbackHandler {} subscribing changes listener to path: {}, callback type: {}, event types: {}, listener: {}, watchChild: {}
September 28th 2021, 09:46:42.665	CallbackHandler {} START: CallbackHandler {}, INVOKE {} listener: {} type: {}
September 28th 2021, 09:46:42.665	CallbackHandler {} START: CallbackHandler {}, INVOKE {} listener: {} type: {}
September 28th 2021, 09:46:42.665	CallbackHandler CallbackHandler {} subscribing changes listener to path: {}, callback type: {}, event types: {}, listener: {}, watchChild: {}
September 28th 2021, 09:46:42.666	CallbackHandler CallbackHandler{}, Subscribing to path: {} took: {}
September 28th 2021, 09:46:42.666	CallbackHandler CallbackHandler{}, Subscribing to path: {} took: {}
September 28th 2021, 09:46:42.667	HelixTaskExecutor No Messages to process
September 28th 2021, 09:46:42.667	HelixTaskExecutor No Messages to process
September 28th 2021, 09:46:42.667	AbstractAsyncBaseStage END AsyncProcess: {}, took {} ms
September 28th 2021, 09:46:42.668	CallbackHandler {} END:INVOKE CallbackHandler {}, {} listener: {} type: {} Took: {}ms
September 28th 2021, 09:46:42.668	GenericHelixController START: GenericClusterController.onMessage() for cluster lcoo_MyComp
September 28th 2021, 09:46:42.668	CallbackHandler {} END:INVOKE CallbackHandler {}, {} listener: {} type: {} Took: {}ms
September 28th 2021, 09:46:42.668	PropertyCache Event lcoo_MyComp::DEFAULT::cf855014_DEFAULT : Refreshed 7 property StateModelDefinition took 9 ms. Selective: false
September 28th 2021, 09:46:42.668	CallbackHandler CallbackHandler {} subscribing changes listener to path: {}, callback type: {}, event types: {}, listener: {}, watchChild: {}
September 28th 2021, 09:46:42.668	CallbackHandler {} START: CallbackHandler {}, INVOKE {} listener: {} type: {}
September 28th 2021, 09:46:42.668	CallbackHandler CallbackHandler{}, Subscribing to path: {} took: {}
September 28th 2021, 09:46:42.669	GenericHelixController END: GenericClusterController.onMessage() for cluster lcoo_MyComp
September 28th 2021, 09:46:42.669	CallbackHandler {} END:INVOKE CallbackHandler {}, {} listener: {} type: {} Took: {}ms
September 28th 2021, 09:46:42.669	PropertyCache Event lcoo_MyComp::DEFAULT::cf855014_DEFAULT : Refreshed 0 property ClusterConstraint took 1 ms. Selective: false
September 28th 2021, 09:46:42.670	InstanceMessagesCache START: InstanceMessagesCache.refresh()
September 28th 2021, 09:46:42.671	AbstractDataCache Event lcoo_MyComp::TASK::9375e6b8_TASK : 0 properties refreshed from ZK.
September 28th 2021, 09:46:42.671	ParticipantStateCache Event lcoo_MyComp::TASK::9375e6b8_TASK : END: participantStateCache.refresh() for cluster lcoo_MyComp, started at : 1632815202649, took 22 ms
September 28th 2021, 09:46:42.672	Pipeline END ResourceValidationStage for TASK pipeline for cluster lcoo_MyComp. took: 0 ms for event 9375e6b8_TASK
September 28th 2021, 09:46:42.672	Pipeline END ResourceComputationStage for TASK pipeline for cluster lcoo_MyComp. took: 0 ms for event 9375e6b8_TASK
September 28th 2021, 09:46:42.672	Pipeline END ReadClusterDataStage for TASK pipeline for cluster lcoo_MyComp. took: 56 ms for event 9375e6b8_TASK
September 28th 2021, 09:46:42.672	Pipeline END CurrentStateComputationStage for TASK pipeline for cluster lcoo_MyComp. took: 0 ms for event 9375e6b8_TASK
September 28th 2021, 09:46:42.672	AssignableInstanceManager AssignableInstanceManager built AssignableInstances from scratch based on CurrentState.
September 28th 2021, 09:46:42.672	WorkflowControllerDataProvider Event 9375e6b8_TASK : END: WorkflowControllerDataProvider.refresh() for cluster lcoo_MyComp, started at 1632815202616 took 56 for TASK pipeline
September 28th 2021, 09:46:42.673	AbstractAsyncBaseStage START AsyncProcess: {}
September 28th 2021, 09:46:42.673	Pipeline END TaskSchedulingStage for TASK pipeline for cluster lcoo_MyComp. took: 1 ms for event 9375e6b8_TASK
September 28th 2021, 09:46:42.673	TaskPersistDataStage START TaskPersistDataStage.process()
September 28th 2021, 09:46:42.673	AssignableInstanceManager Current quota capacity: {}
September 28th 2021, 09:46:42.673	Pipeline END TaskGarbageCollectionStage for TASK pipeline for cluster lcoo_MyComp. took: 0 ms for event 9375e6b8_TASK
September 28th 2021, 09:46:42.673	AbstractAsyncBaseStage Submitted asynchronous {} task to worker
September 28th 2021, 09:46:42.673	TaskPersistDataStage END TaskPersistDataStage.process() for cluster {} took {} ms
September 28th 2021, 09:46:42.673	Pipeline END TaskPersistDataStage for TASK pipeline for cluster lcoo_MyComp. took: 0 ms for event 9375e6b8_TASK
September 28th 2021, 09:46:42.674	BaseControllerDataProvider Event cf855014_TASK : No instance config change for lcoo_MyComp cluster, TASK pipeline
September 28th 2021, 09:46:42.674	Pipeline END TaskMessageDispatchStage for TASK pipeline for cluster lcoo_MyComp. took: 0 ms for event 9375e6b8_TASK
September 28th 2021, 09:46:42.674	AbstractAsyncBaseStage END AsyncProcess: {}, took {} ms
September 28th 2021, 09:46:42.674	GenericHelixController START: Invoking {} controller pipeline for cluster: {}. Event type: {}, ID: {}. Event session ID: {}
September 28th 2021, 09:46:42.674	GenericHelixController END: Invoking {} controller pipeline for event {}::{} for cluster {}, took {} ms
September 28th 2021, 09:46:42.674	BaseControllerDataProvider Event cf855014_TASK : No live instance change for lcoo_MyComp cluster, TASK pipeline
September 28th 2021, 09:46:42.674	BaseControllerDataProvider Event cf855014_TASK : No ideal state change for lcoo_MyComp cluster, TASK pipeline
September 28th 2021, 09:46:42.674	GenericHelixController Controller stopping periodical rebalance timer at period 9223372036854775807
September 28th 2021, 09:46:42.674	Pipeline END TaskMessageGenerationPhase for TASK pipeline for cluster lcoo_MyComp. took: 0 ms for event 9375e6b8_TASK
September 28th 2021, 09:46:42.674	BaseControllerDataProvider Event cf855014_TASK : No resource config change for lcoo_MyComp cluster, TASK pipeline
September 28th 2021, 09:46:42.674	BaseControllerDataProvider Event cf855014_TASK : No ClusterConfig change for cluster lcoo_MyComp, pipeline TASK
September 28th 2021, 09:46:42.676	PropertyCache Event lcoo_MyComp::TASK::cf855014_TASK : Refreshed 0 property ClusterConstraint took 0 ms. Selective: false
September 28th 2021, 09:46:42.676	PropertyCache Event lcoo_MyComp::TASK::cf855014_TASK : Refreshed 7 property StateModelDefinition took 1 ms. Selective: false
September 28th 2021, 09:46:42.677	InstanceMessagesCache START: InstanceMessagesCache.refresh()
September 28th 2021, 09:46:42.682	InstanceMessagesCache Start to refresh stale message cache
September 28th 2021, 09:46:42.682	InstanceMessagesCache END: InstanceMessagesCache.refresh(), {} of Messages read from ZooKeeper. took {} ms. 
September 28th 2021, 09:46:42.689	InstanceMessagesCache Start to refresh stale message cache
September 28th 2021, 09:46:42.689	InstanceMessagesCache END: InstanceMessagesCache.refresh(), {} of Messages read from ZooKeeper. took {} ms. 
September 28th 2021, 09:46:42.696	AbstractDataCache Event lcoo_MyComp::DEFAULT::cf855014_DEFAULT : 0 properties refreshed from ZK.
September 28th 2021, 09:46:42.697	Pipeline END ReadClusterDataStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 38 ms for event cf855014_DEFAULT
September 28th 2021, 09:46:42.697	ParticipantStateCache Event lcoo_MyComp::DEFAULT::cf855014_DEFAULT : END: participantStateCache.refresh() for cluster lcoo_MyComp, started at : 1632815202697, took 0 ms
September 28th 2021, 09:46:42.697	AbstractDataCache Event lcoo_MyComp::DEFAULT::cf855014_DEFAULT : 0 properties refreshed from ZK.
September 28th 2021, 09:46:42.697	ParticipantStateCache Event lcoo_MyComp::DEFAULT::cf855014_DEFAULT : END: participantStateCache.refresh() for cluster lcoo_MyComp, started at : 1632815202682, took 14 ms
September 28th 2021, 09:46:42.697	InstanceMessagesCache END: updateRelayMessages(), {} of valid relay messages in cache, took {} ms. 
September 28th 2021, 09:46:42.697	Pipeline END ResourceComputationStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event cf855014_DEFAULT
September 28th 2021, 09:46:42.697	ResourceControllerDataProvider Event cf855014_DEFAULT : END: ResourceControllerDataProvider.refresh() for cluster lcoo_MyComp, started at 1632815202659 took 38 for DEFAULT pipeline
September 28th 2021, 09:46:42.697	ResourceControllerDataProvider Event cf855014_DEFAULT : No customized state config change for lcoo_MyComp cluster, DEFAULT pipeline
September 28th 2021, 09:46:42.698	Pipeline END ResourceValidationStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event cf855014_DEFAULT
September 28th 2021, 09:46:42.698	Pipeline END ExternalViewComputeStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event cf855014_DEFAULT
September 28th 2021, 09:46:42.698	AbstractAsyncBaseStage START AsyncProcess: {}
September 28th 2021, 09:46:42.698	AbstractAsyncBaseStage Submitted asynchronous {} task to worker
September 28th 2021, 09:46:42.698	Pipeline END TopStateHandoffReportStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event cf855014_DEFAULT
September 28th 2021, 09:46:42.698	Pipeline END CurrentStateComputationStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event cf855014_DEFAULT
September 28th 2021, 09:46:42.698	Pipeline END CustomizedStateComputationStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event cf855014_DEFAULT
September 28th 2021, 09:46:42.699	WagedRebalancer Start calculating the new best possible assignment.
September 28th 2021, 09:46:42.699	AbstractAsyncBaseStage END AsyncProcess: {}, took {} ms
September 28th 2021, 09:46:42.699	WagedRebalancer Start computing new ideal states for resources: {}
September 28th 2021, 09:46:42.700	WagedRebalancer Finish calculating an assignment with algorithm {}. Took: {} ms.
September 28th 2021, 09:46:42.700	WagedRebalancer Finish calculating the new best possible assignment.
September 28th 2021, 09:46:42.700	DelayedAutoRebalancer Computing IdealState for MyCompServiceResource
September 28th 2021, 09:46:42.700	WagedRebalancer Finish computing new ideal states for resources: {}
September 28th 2021, 09:46:42.700	WagedRebalancer Start calculating for an assignment with algorithm {}
September 28th 2021, 09:46:42.702	Pipeline END ResourceMessageGenerationPhase for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event cf855014_DEFAULT
September 28th 2021, 09:46:42.702	Pipeline END MaintenanceRecoveryStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event cf855014_DEFAULT
September 28th 2021, 09:46:42.702	AbstractAsyncBaseStage Submitted asynchronous {} task to worker
September 28th 2021, 09:46:42.702	Pipeline END IntermediateStateCalcStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event cf855014_DEFAULT
September 28th 2021, 09:46:42.702	AbstractAsyncBaseStage END AsyncProcess: {}, took {} ms
September 28th 2021, 09:46:42.702	StateTransitionThrottleController No throttle config is set!
September 28th 2021, 09:46:42.702	Pipeline END BestPossibleStateCalcStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 3 ms for event cf855014_DEFAULT
September 28th 2021, 09:46:42.702	AbstractAsyncBaseStage START AsyncProcess: {}
September 28th 2021, 09:46:42.703	MessageDispatchStage Event cf855014_DEFAULT : Sending Message b4ba7df0-9265-4b35-b643-e3f3d676d1e4 to 10.200.32.108-1931 transit MyCompServiceResource.MyCompServiceResource_0|[] from:ONLINE to:OFFLINE, relayMessages: 0

bojanv55 avatar Sep 29 '21 14:09 bojanv55

And this is the log that lead to transition from OFFLINE to DROPPED:

September 28th 2021, 09:46:47.924	OnlineOfflineStateModel Recreated queues for partition MyCompServiceResource_0
September 28th 2021, 09:46:47.924	OnlineOfflineStateModel Recreated queues for partition MyCompServiceResource_0
September 28th 2021, 09:46:47.933	OnlineOfflineStateModel Recreated queues for partition MyCompServiceResource_0
September 28th 2021, 09:46:47.933	OnlineOfflineStateModel Recreated queues for partition MyCompServiceResource_0
September 28th 2021, 09:46:47.941	OnlineOfflineStateModel Recreated queues for partition MyCompServiceResource_0
September 28th 2021, 09:46:47.941	OnlineOfflineStateModel Recreated queues for partition MyCompServiceResource_0
September 28th 2021, 09:46:47.949	OnlineOfflineStateModel Recreated queues for partition MyCompServiceResource_0
September 28th 2021, 09:46:47.949	OnlineOfflineStateModel Recreated queues for partition MyCompServiceResource_0
September 28th 2021, 09:46:47.963	OnlineOfflineStateModel Recreated queues for partition MyCompServiceResource_0
September 28th 2021, 09:46:47.963	OnlineOfflineStateModel Recreated queues for partition MyCompServiceResource_0
September 28th 2021, 09:46:47.971	OnlineOfflineStateModel Recreated queues for partition MyCompServiceResource_0
September 28th 2021, 09:46:47.971	OnlineOfflineStateModel Recreated queues for partition MyCompServiceResource_0
September 28th 2021, 09:46:47.978	OnlineOfflineStateModel Recreated queues for partition MyCompServiceResource_0
September 28th 2021, 09:46:47.978	OnlineOfflineStateModel Recreated queues for partition MyCompServiceResource_0
September 28th 2021, 09:46:47.984	OnlineOfflineStateModel Recreated queues for partition MyCompServiceResource_0
September 28th 2021, 09:46:47.984	OnlineOfflineStateModel Recreated queues for partition MyCompServiceResource_0
September 28th 2021, 09:46:47.992	OnlineOfflineStateModel Recreated queues for partition MyCompServiceResource_0
September 28th 2021, 09:46:47.992	OnlineOfflineStateModel Recreated queues for partition MyCompServiceResource_0
September 28th 2021, 09:46:47.999	OnlineOfflineStateModel Recreated queues for partition MyCompServiceResource_0
September 28th 2021, 09:46:47.999	OnlineOfflineStateModel Recreated queues for partition MyCompServiceResource_0
September 28th 2021, 09:46:48.008	GenericHelixController START: GenericClusterController.onStateChange()
September 28th 2021, 09:46:48.008	CallbackHandler {} START: CallbackHandler {}, INVOKE {} listener: {} type: {}
September 28th 2021, 09:46:48.009	GenericHelixController Controller stopping periodical rebalance timer at period 9223372036854775807
September 28th 2021, 09:46:48.009	GenericHelixController Controller stopping periodical rebalance timer at period 9223372036854775807
September 28th 2021, 09:46:48.009	GenericHelixController END: GenericClusterController.onStateChange()
September 28th 2021, 09:46:48.009	CallbackHandler {} END:INVOKE CallbackHandler {}, {} listener: {} type: {} Took: {}ms
September 28th 2021, 09:46:48.010	BaseControllerDataProvider Event 459453cc_TASK : No live instance change for lcoo_MyComp cluster, TASK pipeline
September 28th 2021, 09:46:48.010	BaseControllerDataProvider Event 459453cc_DEFAULT : No ClusterConfig change for cluster lcoo_MyComp, pipeline DEFAULT
September 28th 2021, 09:46:48.010	GenericHelixController START: Invoking {} controller pipeline for cluster: {}. Event type: {}, ID: {}. Event session ID: {}
September 28th 2021, 09:46:48.010	BaseControllerDataProvider Event 459453cc_TASK : No ideal state change for lcoo_MyComp cluster, TASK pipeline
September 28th 2021, 09:46:48.010	BaseControllerDataProvider Event 459453cc_TASK : No ClusterConfig change for cluster lcoo_MyComp, pipeline TASK
September 28th 2021, 09:46:48.010	GenericHelixController START: Invoking {} controller pipeline for cluster: {}. Event type: {}, ID: {}. Event session ID: {}
September 28th 2021, 09:46:48.011	BaseControllerDataProvider Event 459453cc_DEFAULT : No resource config change for lcoo_MyComp cluster, DEFAULT pipeline
September 28th 2021, 09:46:48.011	BaseControllerDataProvider Event 459453cc_TASK : No resource config change for lcoo_MyComp cluster, TASK pipeline
September 28th 2021, 09:46:48.011	BaseControllerDataProvider Event 459453cc_DEFAULT : No live instance change for lcoo_MyComp cluster, DEFAULT pipeline
September 28th 2021, 09:46:48.011	BaseControllerDataProvider Event 459453cc_DEFAULT : No ideal state change for lcoo_MyComp cluster, DEFAULT pipeline
September 28th 2021, 09:46:48.011	BaseControllerDataProvider Event 459453cc_DEFAULT : No instance config change for lcoo_MyComp cluster, DEFAULT pipeline
September 28th 2021, 09:46:48.011	BaseControllerDataProvider Event 459453cc_TASK : No instance config change for lcoo_MyComp cluster, TASK pipeline
September 28th 2021, 09:46:48.013	PropertyCache Event lcoo_MyComp::TASK::459453cc_TASK : Refreshed 7 property StateModelDefinition took 2 ms. Selective: false
September 28th 2021, 09:46:48.013	PropertyCache Event lcoo_MyComp::DEFAULT::459453cc_DEFAULT : Refreshed 7 property StateModelDefinition took 2 ms. Selective: false
September 28th 2021, 09:46:48.027	PropertyCache Event lcoo_MyComp::DEFAULT::459453cc_DEFAULT : Refreshed 0 property ClusterConstraint took 13 ms. Selective: false
September 28th 2021, 09:46:48.027	HelixTask Message b4ba7df0-9265-4b35-b643-e3f3d676d1e4 completed.
September 28th 2021, 09:46:48.027	HelixTask Message b4ba7df0-9265-4b35-b643-e3f3d676d1e4 completed.
September 28th 2021, 09:46:48.027	InstanceMessagesCache START: InstanceMessagesCache.refresh()
September 28th 2021, 09:46:48.027	InstanceMessagesCache START: InstanceMessagesCache.refresh()
September 28th 2021, 09:46:48.027	PropertyCache Event lcoo_MyComp::TASK::459453cc_TASK : Refreshed 0 property ClusterConstraint took 14 ms. Selective: false
September 28th 2021, 09:46:48.032	HelixTask Delete message b4ba7df0-9265-4b35-b643-e3f3d676d1e4 from zk!
September 28th 2021, 09:46:48.032	HelixTask Delete message b4ba7df0-9265-4b35-b643-e3f3d676d1e4 from zk!
September 28th 2021, 09:46:48.033	CallbackHandler CallbackHandler {} subscribing changes listener to path: {}, callback type: {}, event types: {}, listener: {}, watchChild: {}
September 28th 2021, 09:46:48.033	HelixTaskExecutor message finished: b4ba7df0-9265-4b35-b643-e3f3d676d1e4, took 5172
September 28th 2021, 09:46:48.033	CallbackHandler {} START: CallbackHandler {}, INVOKE {} listener: {} type: {}
September 28th 2021, 09:46:48.033	MBeanRegistrar MBean {} has been registered.
September 28th 2021, 09:46:48.033	MBeanRegistrar MBean {} has been registered.
September 28th 2021, 09:46:48.033	HelixTaskExecutor message finished: b4ba7df0-9265-4b35-b643-e3f3d676d1e4, took 5172
September 28th 2021, 09:46:48.034	GenericHelixController END: GenericClusterController.onMessage() for cluster lcoo_MyComp
September 28th 2021, 09:46:48.034	GenericHelixController START: GenericClusterController.onMessage() for cluster lcoo_MyComp
September 28th 2021, 09:46:48.034	CallbackHandler CallbackHandler{}, Subscribing to path: {} took: {}
September 28th 2021, 09:46:48.034	HelixTask Message: {} (parent: {}) handling task for {}:{} completed at: {}, results: {}. FrameworkTime: {} ms; HandlerTime: {} ms.
September 28th 2021, 09:46:48.034	HelixTask Message: {} (parent: {}) handling task for {}:{} completed at: {}, results: {}. FrameworkTime: {} ms; HandlerTime: {} ms.
September 28th 2021, 09:46:48.035	CallbackHandler {} END:INVOKE CallbackHandler {}, {} listener: {} type: {} Took: {}ms
September 28th 2021, 09:46:48.036	CallbackHandler {} START: CallbackHandler {}, INVOKE {} listener: {} type: {}
September 28th 2021, 09:46:48.036	CallbackHandler {} START: CallbackHandler {}, INVOKE {} listener: {} type: {}
September 28th 2021, 09:46:48.037	CallbackHandler CallbackHandler {} subscribing changes listener to path: {}, callback type: {}, event types: {}, listener: {}, watchChild: {}
September 28th 2021, 09:46:48.037	CallbackHandler CallbackHandler {} subscribing changes listener to path: {}, callback type: {}, event types: {}, listener: {}, watchChild: {}
September 28th 2021, 09:46:48.038	CallbackHandler CallbackHandler{}, Subscribing to path: {} took: {}
September 28th 2021, 09:46:48.038	CallbackHandler CallbackHandler{}, Subscribing to path: {} took: {}
September 28th 2021, 09:46:48.039	CallbackHandler {} END:INVOKE CallbackHandler {}, {} listener: {} type: {} Took: {}ms
September 28th 2021, 09:46:48.039	CallbackHandler {} END:INVOKE CallbackHandler {}, {} listener: {} type: {} Took: {}ms
September 28th 2021, 09:46:48.039	HelixTaskExecutor No Messages to process
September 28th 2021, 09:46:48.039	HelixTaskExecutor No Messages to process
September 28th 2021, 09:46:48.043	InstanceMessagesCache END: InstanceMessagesCache.refresh(), {} of Messages read from ZooKeeper. took {} ms. 
September 28th 2021, 09:46:48.043	InstanceMessagesCache Start to refresh stale message cache
September 28th 2021, 09:46:48.043	InstanceMessagesCache Start to refresh stale message cache
September 28th 2021, 09:46:48.043	InstanceMessagesCache END: InstanceMessagesCache.refresh(), {} of Messages read from ZooKeeper. took {} ms. 
September 28th 2021, 09:46:48.057	ParticipantStateCache Event lcoo_MyComp::DEFAULT::459453cc_DEFAULT : END: participantStateCache.refresh() for cluster lcoo_MyComp, started at : 1632815208043, took 14 ms
September 28th 2021, 09:46:48.057	AbstractDataCache Event lcoo_MyComp::DEFAULT::459453cc_DEFAULT : 1 properties refreshed from ZK.
September 28th 2021, 09:46:48.058	Pipeline END ReadClusterDataStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 48 ms for event 459453cc_DEFAULT
September 28th 2021, 09:46:48.058	ResourceControllerDataProvider Event 459453cc_DEFAULT : No customized state config change for lcoo_MyComp cluster, DEFAULT pipeline
September 28th 2021, 09:46:48.058	Pipeline END ResourceComputationStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 459453cc_DEFAULT
September 28th 2021, 09:46:48.058	InstanceMessagesCache END: updateRelayMessages(), {} of valid relay messages in cache, took {} ms. 
September 28th 2021, 09:46:48.058	InstanceMessagesCache END: updateRelayMessages(), {} of valid relay messages in cache, took {} ms. 
September 28th 2021, 09:46:48.058	ResourceControllerDataProvider Event 459453cc_DEFAULT : END: ResourceControllerDataProvider.refresh() for cluster lcoo_MyComp, started at 1632815208010 took 48 for DEFAULT pipeline
September 28th 2021, 09:46:48.058	AbstractDataCache Event lcoo_MyComp::DEFAULT::459453cc_DEFAULT : 0 properties refreshed from ZK.
September 28th 2021, 09:46:48.058	ParticipantStateCache Event lcoo_MyComp::DEFAULT::459453cc_DEFAULT : END: participantStateCache.refresh() for cluster lcoo_MyComp, started at : 1632815208058, took 0 ms
September 28th 2021, 09:46:48.058	AbstractDataCache Event lcoo_MyComp::TASK::459453cc_TASK : 1 properties refreshed from ZK.
September 28th 2021, 09:46:48.058	ParticipantStateCache Event lcoo_MyComp::TASK::459453cc_TASK : END: participantStateCache.refresh() for cluster lcoo_MyComp, started at : 1632815208044, took 14 ms
September 28th 2021, 09:46:48.059	AbstractAsyncBaseStage Submitted asynchronous {} task to worker
September 28th 2021, 09:46:48.059	Pipeline END CustomizedStateComputationStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 459453cc_DEFAULT
September 28th 2021, 09:46:48.059	Pipeline END ExternalViewComputeStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 459453cc_DEFAULT
September 28th 2021, 09:46:48.059	Pipeline END ResourceValidationStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 459453cc_DEFAULT
September 28th 2021, 09:46:48.059	AbstractAsyncBaseStage START AsyncProcess: {}
September 28th 2021, 09:46:48.059	Pipeline END TopStateHandoffReportStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 459453cc_DEFAULT
September 28th 2021, 09:46:48.059	Pipeline END CurrentStateComputationStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 459453cc_DEFAULT
September 28th 2021, 09:46:48.060	WagedRebalancer Start computing new ideal states for resources: {}
September 28th 2021, 09:46:48.060	WagedRebalancer Finish calculating the new best possible assignment.
September 28th 2021, 09:46:48.060	WagedRebalancer Finish calculating an assignment with algorithm {}. Took: {} ms.
September 28th 2021, 09:46:48.060	WagedRebalancer Start calculating for an assignment with algorithm {}
September 28th 2021, 09:46:48.060	WagedRebalancer Start calculating the new best possible assignment.
September 28th 2021, 09:46:48.061	WagedRebalancer Finish computing new ideal states for resources: {}
September 28th 2021, 09:46:48.061	StateTransitionThrottleController No throttle config is set!
September 28th 2021, 09:46:48.061	Pipeline END BestPossibleStateCalcStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 1 ms for event 459453cc_DEFAULT
September 28th 2021, 09:46:48.062	Pipeline END ResourceMessageGenerationPhase for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 459453cc_DEFAULT
September 28th 2021, 09:46:48.062	Pipeline END MaintenanceRecoveryStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 459453cc_DEFAULT
September 28th 2021, 09:46:48.062	AbstractAsyncBaseStage END AsyncProcess: {}, took {} ms
September 28th 2021, 09:46:48.062	AbstractAsyncBaseStage Submitted asynchronous {} task to worker
September 28th 2021, 09:46:48.062	AbstractAsyncBaseStage START AsyncProcess: {}
September 28th 2021, 09:46:48.062	Pipeline END IntermediateStateCalcStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 1 ms for event 459453cc_DEFAULT
September 28th 2021, 09:46:48.063	Pipeline END MessageSelectionStage for DEFAULT pipeline for cluster lcoo_MyComp. took: 0 ms for event 459453cc_DEFAULT
September 28th 2021, 09:46:48.063	MessageDispatchStage Event 459453cc_DEFAULT : Sending Message 93472683-f9d5-4d70-b10e-d3f8c5e3b85a to 10.200.32.108-1931 transit MyCompServiceResource.MyCompServiceResource_0|[] from:OFFLINE to:DROPPED, relayMessages: 0

bojanv55 avatar Sep 29 '21 14:09 bojanv55

Hello @bojanv55 - i am part of Helix core dev team here at @LinkedIn. I am trying to understand if this issue still exists?

If possible, can you please close the issue if not reproducible. thanks, komal

desaikomal avatar May 24 '23 14:05 desaikomal