Created
May 1, 2018 17:55
-
-
Save shanthoosh/55410fe4ebf3cfb65281b35f16397cad to your computer and use it in GitHub Desktop.
Sample exception logs.
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
--- Shutdown of current leader. Leader joins the group as follower. | |
1074 00:26:10.274 [DEBUG] [TestEventLogger] 122723 [ZkClient-EventThread-585-127.0.0.1:54727] WARN org.apache.samza.zk.ZkJobCoordinator - Got Disconnected event for processor=2. Scheduling a coordinator stop. | |
1075 00:26:10.275 [DEBUG] [TestEventLogger] 122724 [ZkClient-EventThread-585-127.0.0.1:54727] INFO org.apache.samza.zk.ScheduleAfterDebounceTime - Scheduled action: ZK_SESSION_ERROR to run after: 500 milliseconds. | |
1076 00:26:10.275 [DEBUG] [TestEventLogger] 122724 [ZkClient-EventThread-585-127.0.0.1:54727] WARN org.apache.samza.zk.ZkJobCoordinator - Got Expired event for processor=2. Stopping the container and unregister the processor node. | |
1077 00:26:10.276 [DEBUG] [TestEventLogger] 122724 [ZkClient-EventThread-585-127.0.0.1:54727] INFO org.apache.samza.processor.StreamProcessor - Shutting down container in onJobModelExpired for processor:2 | |
1078 00:26:10.276 [DEBUG] [TestEventLogger] 122724 [p-2-container-thread-0] INFO org.apache.samza.container.SamzaContainer - Shutting down. | |
1079 00:26:10.277 [DEBUG] [TestEventLogger] 122726 [p-2-container-thread-0] INFO org.apache.samza.container.SamzaContainer - Shutting down consumer multiplexer. | |
1080 00:26:10.277 [DEBUG] [TestEventLogger] 122726 [p-2-container-thread-0] INFO org.apache.samza.system.kafka.BrokerProxy - Shutting down BrokerProxy for localhost:54730 | |
1081 00:26:10.278 [DEBUG] [TestEventLogger] 122726 [p-2-container-thread-0] INFO org.apache.samza.system.kafka.BrokerProxy - closing simple consumer... | |
1082 00:26:10.289 [DEBUG] [TestEventLogger] 122735 [Samza BrokerProxy BrokerProxy thread pointed at localhost:54730 for client samza_consumer-test_job-1] INFO org.apache.samza.system.kafka.BrokerProxy - Shutting down due to interrupt. | |
1083 00:26:10.289 [DEBUG] [TestEventLogger] 122736 [p-2-container-thread-0] INFO org.apache.samza.container.SamzaContainer - Shutting down task instance stream tasks. | |
1084 00:26:10.290 [DEBUG] [TestEventLogger] 122736 [p-2-container-thread-0] INFO org.apache.samza.container.SamzaContainer - Shutting down timer executor | |
1085 00:26:10.290 [DEBUG] [TestEventLogger] 122736 [p-2-container-thread-0] INFO org.apache.samza.container.SamzaContainer - Committing offsets for all task instances | |
1086 00:26:10.290 [DEBUG] [TestEventLogger] 122736 [p-2-container-thread-0] INFO org.apache.samza.container.SamzaContainer - Shutting down task instance table manager. | |
1087 00:26:10.290 [DEBUG] [TestEventLogger] 122736 [p-2-container-thread-0] INFO org.apache.samza.container.SamzaContainer - Shutting down task instance stores. | |
1088 00:26:10.291 [DEBUG] [TestEventLogger] 122736 [p-2-container-thread-0] INFO org.apache.samza.container.SamzaContainer - Shutting down host statistics monitor. | |
1089 00:26:10.291 [DEBUG] [TestEventLogger] 122736 [p-2-container-thread-0] INFO org.apache.samza.container.SamzaContainer - Shutting down producer multiplexer. | |
1090 00:26:10.291 [DEBUG] [TestEventLogger] 122736 [p-2-container-thread-0] INFO org.apache.samza.system.kafka.KafkaSystemProducer - Stopping producer for system: test_ZKS_test-system1 | |
1091 00:26:10.291 [DEBUG] [TestEventLogger] 122736 [p-2-container-thread-0] INFO org.apache.kafka.clients.producer.KafkaProducer - Closing the Kafka producer with timeoutMillis = 9223372036854775807 ms. | |
1092 00:26:10.292 [DEBUG] [TestEventLogger] 122739 [p-2-container-thread-0] INFO org.apache.samza.container.SamzaContainer - Shutting down offset manager. | |
1093 00:26:10.292 [DEBUG] [TestEventLogger] 122739 [p-2-container-thread-0] INFO org.apache.samza.container.SamzaContainer - Shutting down metrics reporters. | |
1094 00:26:10.292 [DEBUG] [TestEventLogger] 122739 [p-2-container-thread-0] INFO org.apache.samza.container.SamzaContainer - Shutting down JVM metrics. | |
1095 00:26:10.292 [DEBUG] [TestEventLogger] 122739 [p-2-container-thread-0] INFO org.apache.samza.container.SamzaContainer - Shutting down admin multiplexer. | |
1096 00:26:10.293 [DEBUG] [TestEventLogger] 122739 [p-2-container-thread-0] INFO org.apache.samza.container.SamzaContainer - Shutdown complete. | |
1097 00:26:10.293 [DEBUG] [TestEventLogger] 122739 [p-2-container-thread-0] INFO org.apache.samza.processor.StreamProcessor - Container org.apache.samza.container.SamzaContainer@486e9741 stopped due to a request from JobCoordinator. | |
1098 00:26:10.293 [DEBUG] [TestEventLogger] 122740 [Test worker] INFO org.apache.samza.processor.TestZkStreamProcessorBase - Waiting on java.util.concurrent.CountDownLatch@70bb8508[Count = 1] | |
1099 00:26:10.293 [DEBUG] [TestEventLogger] 122740 [ZkClient-EventThread-585-127.0.0.1:54727] INFO org.apache.samza.processor.StreamProcessor - ShutdownComplete=true | |
1100 00:26:10.294 [DEBUG] [TestEventLogger] 122740 [ZkClient-EventThread-585-127.0.0.1:54727] INFO org.apache.samza.processor.StreamProcessor - Shutting down container done for pid=2; complete =true | |
1101 00:26:10.294 [DEBUG] [TestEventLogger] 122740 [ZkClient-EventThread-585-127.0.0.1:54727] INFO org.apache.samza.zk.ZkJobCoordinator - Got new session created event for processor=2 | |
1102 00:26:10.294 [DEBUG] [TestEventLogger] 122740 [ZkClient-EventThread-585-127.0.0.1:54727] INFO org.apache.samza.zk.ZkJobCoordinator - register zk controller for the new session | |
1103 00:26:10.294 [DEBUG] [TestEventLogger] 122742 [ZkClient-EventThread-585-127.0.0.1:54727] INFO org.apache.samza.zk.ZkUtils - Created ephemeral path: /app-test-job-1/test-job-1-coordinationData/processors/0000000002 for processor: svenkata-mn1.linkedin.biz 2 in zookeeper. | |
1104 00:26:10.295 [DEBUG] [TestEventLogger] 122742 [ZkClient-EventThread-585-127.0.0.1:54727] INFO org.apache.samza.zk.ZkUtils - Found these children - [0000000001, 0000000002] | |
1105 00:26:10.295 [DEBUG] [TestEventLogger] 122742 [ZkClient-EventThread-588-127.0.0.1:54727] WARN org.apache.samza.zk.ZkUtils - ALLOWING handleDataChanged for ProcessorChangeHandler from wrong generation. current generation=0; callback generation= 0 | |
1106 00:26:10.295 [DEBUG] [TestEventLogger] 122742 [ZkClient-EventThread-588-127.0.0.1:54727] INFO org.apache.samza.zk.ZkControllerImpl - ZkControllerImpl::ProcessorChangeHandler::handleChildChange - Path: /app-test-job-1/test-job-1-coordinationData/processors Current Children: [0000000001, 0000000002] | |
1107 00:26:10.295 [DEBUG] [TestEventLogger] 122743 [ZkClient-EventThread-588-127.0.0.1:54727] INFO org.apache.samza.zk.ZkJobCoordinator - ZkJobCoordinator::onProcessorChange - list of processors changed! List size=2 | |
1108 00:26:10.295 [DEBUG] [TestEventLogger] 122743 [ZkClient-EventThread-588-127.0.0.1:54727] INFO org.apache.samza.zk.ScheduleAfterDebounceTime - Attempting to cancel the future of action: OnProcessorChange | |
1109 00:26:10.296 [DEBUG] [TestEventLogger] 122743 [ZkClient-EventThread-588-127.0.0.1:54727] INFO org.apache.samza.zk.ScheduleAfterDebounceTime - Scheduled action: OnProcessorChange to run after: 3000 milliseconds. | |
1110 00:26:10.297 [DEBUG] [TestEventLogger] 122743 [ZkClient-EventThread-585-127.0.0.1:54727] INFO org.apache.samza.zk.ZkUtils - Found these children - [0000000001, 0000000002] | |
1111 00:26:10.298 [DEBUG] [TestEventLogger] 122743 [ZkClient-EventThread-585-127.0.0.1:54727] INFO org.apache.samza.zk.ZkLeaderElector - tryBecomeLeader: index = 1 for path=/app-test-job-1/test-job-1-coordinationData/processors/0000000002 out of [0000000001, 0000000002] | |
1112 00:26:10.300 [DEBUG] [TestEventLogger] 122743 [ZkClient-EventThread-585-127.0.0.1:54727] INFO org.apache.samza.zk.ZkLeaderElector - Index = 1 Not eligible to be a leader yet! | |
1113 00:26:10.303 [DEBUG] [TestEventLogger] 122743 [ZkClient-EventThread-585-127.0.0.1:54727] INFO org.apache.samza.zk.ZkLeaderElector - [Processor-2] Subscribing data change for 0000000001 | |
--- Follower becomes leader. | |
1126 00:26:13.278 [DEBUG] [TestEventLogger] 125726 [debounce-thread-0] INFO org.apache.samza.zk.ZkUtils - read the model ver=1 from /app-test-job-1/test-job-1-coordinationData/JobModelGeneration/jobModels/1 | |
1127 00:26:13.302 [DEBUG] [TestEventLogger] 125746 [debounce-thread-0] INFO org.apache.samza.coordinator.JobModelManager$ - SystemStreamPartitionGrouper org.apache.samza.container.grouper.stream.GroupByPartition@7f124766 has grouped the SystemStreamPartitions into 5 tasks with the following taskNames: [Partitio n 1, Partition 0, Partition 3, Partition 2, Partition 4] | |
1128 00:26:13.302 [DEBUG] [TestEventLogger] 125748 [debounce-thread-0] INFO org.apache.samza.zk.ZkUtils - Found these children - [0000000001, 0000000002] | |
1129 00:26:13.303 [DEBUG] [TestEventLogger] 125748 [debounce-thread-0] INFO org.apache.samza.zk.ZkUtils - Found these processorIds - [2, 3] | |
1130 00:26:13.303 [DEBUG] [TestEventLogger] 125748 [debounce-thread-0] INFO org.apache.samza.zk.ZkJobCoordinator - Generating new JobModel with processors: [2, 3]. | |
1131 00:26:13.311 [DEBUG] [TestEventLogger] 125749 [debounce-thread-0] INFO org.apache.samza.zk.ZkJobCoordinator - pid=2Generated new JobModel with version: 2 and processors: [3] | |
1132 00:26:13.323 [DEBUG] [TestEventLogger] 125766 [debounce-thread-0] INFO org.apache.samza.zk.ZkUtils - read the model ver=1 from /app-test-job-1/test-job-1-coordinationData/JobModelGeneration/jobModels/1 | |
--- Old leader acts upon stale events in it's debounce queue and generates new JobModel. | |
1223 00:26:13.347 [DEBUG] [TestEventLogger] 125784 [debounce-thread-0] INFO org.apache.samza.zk.ZkUtils - wrote jobModel path =/app-test-job-1/test-job-1-coordinationData/JobModelGeneration/jobModels/2 | |
1224 00:26:13.357 [DEBUG] [TestEventLogger] 125800 [debounce-thread-0] INFO org.apache.samza.coordinator.JobModelManager$ - SystemStreamPartitionGrouper org.apache.samza.container.grouper.stream.GroupByPartition@363633c6 has grouped the SystemStreamPartitions into 5 tasks with the following taskNames: [Partitio n 1, Partition 0, Partition 3, Partition 2, Partition 4] | |
1225 00:26:13.359 [DEBUG] [TestEventLogger] 125808 [debounce-thread-0] INFO org.apache.samza.zk.ZkJobCoordinator - pid=3Generated new JobModel with version: 3 and processors: [2, 3] | |
1226 00:26:13.375 [DEBUG] [TestEventLogger] 125810 [debounce-thread-0] INFO org.apache.samza.zk.ZkBarrierForVersionUpgrade - Subscribing for child changes at /app-test-job-1/test-job-1-coordinationData/JobModelGeneration/jobModelUpgradeBarrier/versionBarriers/barrier_2/barrier_participants | |
1227 00:26:13.378 [DEBUG] [TestEventLogger] 125811 [debounce-thread-0] INFO org.apache.samza.zk.ScheduleAfterDebounceTime - Scheduled action: BarrierAction to run after: 2000 milliseconds. | |
1228 00:26:13.382 [DEBUG] [TestEventLogger] 125812 [debounce-thread-0] INFO org.apache.samza.zk.ZkUtils - publishing new version: 2; oldVersion = 1(1) | |
1229 00:26:13.383 [DEBUG] [TestEventLogger] 125812 [debounce-thread-0] INFO org.apache.samza.zk.ZkUtils - published new version: 2; expected data version = 2(actual data version after update = 2) | |
1230 00:26:13.385 [DEBUG] [TestEventLogger] 125812 [debounce-thread-0] INFO org.apache.samza.zk.ZkJobCoordinator - pid=2Published new Job Model. Version = 2 | |
1231 00:26:13.386 [DEBUG] [TestEventLogger] 125813 [debounce-thread-0] INFO org.apache.samza.zk.ScheduleAfterDebounceTime - Scheduled action: OnCleanUp to run after: 0 milliseconds. | |
-- Old leader goes first and publishes the JobModel. | |
1231 00:26:13.386 [DEBUG] [TestEventLogger] 125813 [debounce-thread-0] INFO org.apache.samza.zk.ScheduleAfterDebounceTime - Scheduled action: OnCleanUp to run after: 0 milliseconds. | |
1232 00:26:13.386 [DEBUG] [TestEventLogger] 125813 [debounce-thread-0] INFO org.apache.samza.zk.ZkUtils - about to delete old barrier paths from /app-test-job-1/test-job-1-coordinationData/JobModelGeneration/jobModelUpgradeBarrier/versionBarriers | |
1233 00:26:13.387 [DEBUG] [TestEventLogger] 125813 [debounce-thread-0] INFO org.apache.samza.zk.ZkUtils - List of all zkNodes: [barrier_2, barrier_1] | |
1234 00:26:13.387 [DEBUG] [TestEventLogger] 125814 [debounce-thread-0] INFO org.apache.samza.zk.ZkUtils - about to delete jm path=/app-test-job-1/test-job-1-coordinationData/JobModelGeneration/jobModels | |
1235 00:26:13.387 [DEBUG] [TestEventLogger] 125815 [ZkClient-EventThread-585-127.0.0.1:54727] WARN org.apache.samza.zk.ZkUtils - SKIPPING handleDataChanged for ZkJobModelVersionChangeHandler from wrong generation. curGen=1; cb gen= 0 | |
1236 00:26:13.387 [DEBUG] [TestEventLogger] 125815 [ZkClient-EventThread-588-127.0.0.1:54727] WARN org.apache.samza.zk.ZkUtils - ALLOWING handleDataChanged for ZkJobModelVersionChangeHandler from wrong generation. current generation=0; callback generation= 0 | |
1237 00:26:13.388 [DEBUG] [TestEventLogger] 125815 [ZkClient-EventThread-588-127.0.0.1:54727] INFO org.apache.samza.zk.ZkControllerImpl - pid=3. Got notification on version update change. path=/app-test-job-1/test-job-1-coordinationData/JobModelGeneration/jobModelVersion; data=2 | |
1238 00:26:13.388 [DEBUG] [TestEventLogger] 125815 [ZkClient-EventThread-588-127.0.0.1:54727] INFO org.apache.samza.zk.ScheduleAfterDebounceTime - Scheduled action: JobModelVersionChange to run after: 0 milliseconds. | |
1239 00:26:13.388 [DEBUG] [TestEventLogger] 125815 [ZkClient-EventThread-585-127.0.0.1:54727] WARN org.apache.samza.zk.ZkUtils - ALLOWING handleDataChanged for ZkJobModelVersionChangeHandler from wrong generation. current generation=1; callback generation= 1 | |
1240 00:26:13.389 [DEBUG] [TestEventLogger] 125815 [ZkClient-EventThread-585-127.0.0.1:54727] INFO org.apache.samza.zk.ZkControllerImpl - pid=2. Got notification on version update change. path=/app-test-job-1/test-job-1-coordinationData/JobModelGeneration/jobModelVersion; data=2 | |
1241 00:26:13.390 [DEBUG] [TestEventLogger] 125815 [ZkClient-EventThread-585-127.0.0.1:54727] INFO org.apache.samza.zk.ScheduleAfterDebounceTime - Scheduled action: JobModelVersionChange to run after: 0 milliseconds. | |
1242 00:26:13.390 [DEBUG] [TestEventLogger] 125815 [debounce-thread-0] INFO org.apache.samza.zk.ZkJobCoordinator - pid=2: new JobModel available | |
1243 00:26:13.391 [DEBUG] [TestEventLogger] 125816 [debounce-thread-0] INFO org.apache.samza.zk.ZkUtils - read the model ver=2 from /app-test-job-1/test-job-1-coordinationData/JobModelGeneration/jobModels/2 | |
--- New leader fails when it tries to publish. | |
1356 00:26:13.416 [DEBUG] [TestEventLogger] 125828 [ZkClient-EventThread-588-127.0.0.1:54727] INFO org.apache.samza.zk.ScheduleAfterDebounceTime - Scheduled action: OnProcessorChange to run after: 3000 milliseconds. | |
1357 00:26:13.416 [DEBUG] [TestEventLogger] 125831 [debounce-thread-0] INFO org.apache.samza.zk.ZkBarrierForVersionUpgrade - Subscribing for child changes at /app-test-job-1/test-job-1-coordinationData/JobModelGeneration/jobModelUpgradeBarrier/versionBarriers/barrier_3/barrier_participants | |
1358 00:26:13.417 [DEBUG] [TestEventLogger] 125832 [debounce-thread-0] INFO org.apache.samza.zk.ScheduleAfterDebounceTime - Scheduled action: BarrierAction to run after: 2000 milliseconds. | |
1359 00:26:13.417 [DEBUG] [TestEventLogger] 125833 [debounce-thread-0] INFO org.apache.samza.zk.ZkUtils - publishing new version: 3; oldVersion = 1(2) | |
1360 00:26:13.417 [DEBUG] [TestEventLogger] 125833 [debounce-thread-0] ERROR org.apache.samza.zk.ScheduleAfterDebounceTime - Execution of action: OnProcessorChange failed. | |
1361 00:26:13.417 [DEBUG] [TestEventLogger] org.apache.samza.SamzaException: Someone changed JobModelVersion while the leader was generating one: expected1, got 2 | |
1362 00:26:13.417 [DEBUG] [TestEventLogger] at org.apache.samza.zk.ZkUtils.publishJobModelVersion(ZkUtils.java:465) | |
1363 00:26:13.417 [DEBUG] [TestEventLogger] at org.apache.samza.zk.ZkJobCoordinator.doOnProcessorChange(ZkJobCoordinator.java:267) | |
1364 00:26:13.418 [DEBUG] [TestEventLogger] at org.apache.samza.zk.ZkJobCoordinator.lambda$onProcessorChange$1(ZkJobCoordinator.java:225) | |
1365 00:26:13.418 [DEBUG] [TestEventLogger] at org.apache.samza.zk.ScheduleAfterDebounceTime.lambda$getScheduleableAction$0(ScheduleAfterDebounceTime.java:153) | |
1366 00:26:13.418 [DEBUG] [TestEventLogger] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) | |
1367 00:26:13.418 [DEBUG] [TestEventLogger] at java.util.concurrent.FutureTask.run(FutureTask.java:266) | |
1368 00:26:13.418 [DEBUG] [TestEventLogger] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) | |
1369 00:26:13.418 [DEBUG] [TestEventLogger] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) | |
1370 00:26:13.419 [DEBUG] [TestEventLogger] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) | |
1371 00:26:13.419 [DEBUG] [TestEventLogger] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) | |
1372 00:26:13.419 [DEBUG] [TestEventLogger] at java.lang.Thread.run(Thread.java:748) | |
1373 00:26:13.419 [DEBUG] [TestEventLogger] 125833 [debounce-thread-0] INFO org.apache.samza.zk.ScheduleAfterDebounceTime - Shutting down debounce timer! | |
1374 00:26:13.419 [DEBUG] [TestEventLogger] 125833 [debounce-thread-0] ERROR org.apache.samza.zk.ZkJobCoordinator - Received exception in debounce timer! Stopping the job coordinator | |
1375 00:26:13.420 [DEBUG] [TestEventLogger] org.apache.samza.SamzaException: Someone changed JobModelVersion while the leader was generating one: expected1, got 2 | |
1376 00:26:13.420 [DEBUG] [TestEventLogger] at org.apache.samza.zk.ZkUtils.publishJobModelVersion(ZkUtils.java:465) | |
1377 00:26:13.420 [DEBUG] [TestEventLogger] at org.apache.samza.zk.ZkJobCoordinator.doOnProcessorChange(ZkJobCoordinator.java:267) | |
1378 00:26:13.420 [DEBUG] [TestEventLogger] at org.apache.samza.zk.ZkJobCoordinator.lambda$onProcessorChange$1(ZkJobCoordinator.java:225) | |
1379 00:26:13.420 [DEBUG] [TestEventLogger] at org.apache.samza.zk.ScheduleAfterDebounceTime.lambda$getScheduleableAction$0(ScheduleAfterDebounceTime.java:153) | |
1380 00:26:13.420 [DEBUG] [TestEventLogger] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) | |
1381 00:26:13.421 [DEBUG] [TestEventLogger] at java.util.concurrent.FutureTask.run(FutureTask.java:266) | |
1382 00:26:13.421 [DEBUG] [TestEventLogger] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) | |
1383 00:26:13.421 [DEBUG] [TestEventLogger] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) | |
1384 00:26:13.422 [DEBUG] [TestEventLogger] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) | |
1385 00:26:13.422 [DEBUG] [TestEventLogger] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) | |
1386 00:26:13.422 [DEBUG] [TestEventLogger] at java.lang.Thread.run(Thread.java:748) | |
1387 00:26:13.422 [DEBUG] [TestEventLogger] 125834 [debounce-thread-0] INFO org.apache.samza.zk.ZkJobCoordinator - Shutting down Job Coordinator... |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment