search

uber / uReplicator

Improvement of Apache Kafka Mirrormaker
Apache License 2.0
917 stars 199 forks source link

Destination Cluster create 2 topic when enableAutoWhitelist false #278

Closed dungnt081191 closed 5 years ago

dungnt081191 commented 5 years ago

Hi buddies, Overview : When enableAutoWhitelist false, Destination Cluster create 2 topic : 1st topic : same topic name of Source Cluster 2nd topic : topic name in topicmapping.properties .

Branch : Master/branch1.0 have the same issue

Below is my detail config : cluster.properties

kafka.cluster.zkStr.cluster1=source_cluster1:2181,source_cluster2:2181
kafka.cluster.servers.cluster1=source_cluster1:9092,source_cluster2:9092
kafka.cluster.zkStr.cluster2=dest_cluster1:2181,dest_cluster2:2181,dest_cluster3:2181
kafka.cluster.servers.cluster2=dest_cluster1:9093,dest_cluster2:9093,dest_cluster3:9093

consumer.properties

zookeeper.connect=source_cluster1:2181,source_cluster2:2181
bootstrap.servers=source_cluster1:9092,source_cluster2:9092
zookeeper.connection.timeout.ms=30000
zookeeper.session.timeout.ms=30000
group.id=kloak-mirrormaker-test
consumer.id=kloakmms01-sjc1
socket.receive.buffer.bytes=1048576
fetch.message.max.bytes=8388608
queued.max.message.chunks=5
key.deserializer=org.apache.kafka.common.serialization.ByteArrayDeserializer
value.deserializer=org.apache.kafka.common.serialization.ByteArrayDeserializer
auto.offset.reset=smallest

producer.properties

bootstrap.servers=vep-kafka-1.int.vinid.dev:9093,vep-kafka-2.int.vinid.dev:9093,vep-kafka-3.int.vinid.dev:9093
client.id=kloak-mirrormaker-test
producer.type=async
key.serializer=org.apache.kafka.common.serialization.ByteArraySerializer
value.serializer=org.apache.kafka.common.serialization.ByteArraySerializer
batch.size=262144
linger.ms=1000
buffer.memory=167772160
max.request.size=31457280
send.buffer.bytes=62914560
max.in.flight.requests.per.connection=5
delivery.timeout.ms=600000
request.timeout.ms=30000

#SSL
security.protocol=SSL
ssl.truststore.location=
ssl.truststore.password=
ssl.keystore.location=
ssl.keystore.password=
ssl.key.password=

dstzk.properties

enable=false
zkServer=source_cluster1:2181,source_cluster2:2181

helix.properties

zkServer=source_cluster1:2181,source_cluster2:2181
instanceId=testHelixMirrorMaker01
helixClusterName=uReplicatorDev
federated.deployment.name=uReplicator-Tests
enableAutowhitelist=false
port=9000
srckafkaZkpath=source_cluster1:2181,source_cluster2:2181
destKafkaZkpath=dest_cluster1:2181,dest_cluster2:2181,dest_cluster3:2181

topicmapping.properties

topic_A new_topic_A
topic_B new_topic_B

zookeeper.properties

# the directory where the snapshot is stored.
dataDir=/tmp/zookeeper
# the port at which the clients will connect
clientPort=2181
# disable the per-ip limit on the number of connections since this is a non-production config
maxClientCnxns=0

Command start Controller : 

./uReplicator-Distribution/target/uReplicator-Distribution-pkg/bin/start-controller.sh -port 9000 -helixClusterName uReplicatorDev -refreshTimeInSeconds 10 -enableAutoWhitelist false -srcKafkaZkPath source_cluster1:2181,source_cluster2:2181 -destKafkaZkPath dest_cluster1:2181,dest_cluster2:2181,dest_cluster3:2181 -zookeeper source_cluster1:2181,source_cluster2:2181

Command start Worker : 

./uReplicator-Distribution/target/uReplicator-Distribution-pkg/bin/start-worker.sh --consumer.config ./config/consumer.properties --producer.config ./config/producer.properties --helix.config ./config/helix.properties --topic.mappings config/topicmapping.properties

Process I Did : step1 - get the name of topic in Source Cluster . want to replicate all message of it to the Destination Cluster with new topic name , define it in topicmapping.properties topic from Source Cluster : topic_A topic want to replicate to in Destination Cluster : new_topic_A

step2 : Start Controller Step3 : Start Worker Step4 : Manually add topic to uReplicator curl -X POST -d '{"topic":"topic_A", "numPartitions":"1"}' http://localhost:9000/topics

Log on Controller : 

2019-10-04T15:44:58.447+0700: Total time for which application threads were stopped: 0,0002796 seconds, Stopping threads took: 0,0000725 seconds
2019-10-04T15:44:58.448+0700: Total time for which application threads were stopped: 0,0001746 seconds, Stopping threads took: 0,0000266 seconds
2019-10-04T15:44:58.449+0700: Total time for which application threads were stopped: 0,0001838 seconds, Stopping threads took: 0,0000243 seconds
2019-10-04T15:44:58.450+0700: Total time for which application threads were stopped: 0,0001662 seconds, Stopping threads took: 0,0000230 seconds
2019-10-04T15:44:58.452+0700: Total time for which application threads were stopped: 0,0003570 seconds, Stopping threads took: 0,0000639 seconds
2019-10-04T15:44:58.454+0700: Total time for which application threads were stopped: 0,0005935 seconds, Stopping threads took: 0,0002768 seconds
2019-10-04T15:44:58.454+0700: Total time for which application threads were stopped: 0,0003136 seconds, Stopping threads took: 0,0000616 seconds
2019-10-04T15:44:58.455+0700: Total time for which application threads were stopped: 0,0003189 seconds, Stopping threads took: 0,0000610 seconds
2019-10-04T15:44:58.456+0700: Total time for which application threads were stopped: 0,0005623 seconds, Stopping threads took: 0,0000689 seconds
2019-10-04T15:44:58.463+0700: Total time for which application threads were stopped: 0,0001029 seconds, Stopping threads took: 0,0000198 seconds
2019-10-04T15:44:58.464+0700: Total time for which application threads were stopped: 0,0000829 seconds, Stopping threads took: 0,0000143 seconds
2019-10-04T15:44:58.464+0700: Total time for which application threads were stopped: 0,0000875 seconds, Stopping threads took: 0,0000138 seconds
2019-10-04T15:44:58.464+0700: Total time for which application threads were stopped: 0,0000669 seconds, Stopping threads took: 0,0000099 seconds
2019-10-04T15:44:58.464+0700: Total time for which application threads were stopped: 0,0000794 seconds, Stopping threads took: 0,0000109 seconds
2019-10-04T15:44:58.464+0700: Total time for which application threads were stopped: 0,0000666 seconds, Stopping threads took: 0,0000091 seconds
2019-10-04T15:44:58.464+0700: Total time for which application threads were stopped: 0,0001297 seconds, Stopping threads took: 0,0000092 seconds
2019-10-04T15:44:58.465+0700: Total time for which application threads were stopped: 0,0000801 seconds, Stopping threads took: 0,0000109 seconds
2019-10-04T15:44:58.465+0700: Total time for which application threads were stopped: 0,0000716 seconds, Stopping threads took: 0,0000095 seconds
2019-10-04T15:44:58.469+0700: Total time for which application threads were stopped: 0,0000934 seconds, Stopping threads took: 0,0000163 seconds
2019-10-04T15:44:58.470+0700: Total time for which application threads were stopped: 0,0000770 seconds, Stopping threads took: 0,0000163 seconds
2019-10-04T15:44:58.470+0700: Total time for which application threads were stopped: 0,0000490 seconds, Stopping threads took: 0,0000083 seconds
2019-10-04T15:44:58.473+0700: Total time for which application threads were stopped: 0,0000833 seconds, Stopping threads took: 0,0000131 seconds
2019-10-04T15:44:58.476+0700: Total time for which application threads were stopped: 0,0001028 seconds, Stopping threads took: 0,0000172 seconds
2019-10-04T15:44:58.476+0700: Total time for which application threads were stopped: 0,0000629 seconds, Stopping threads took: 0,0000094 seconds
2019-10-04T15:44:58.476+0700: Total time for which application threads were stopped: 0,0000480 seconds, Stopping threads took: 0,0000068 seconds
2019-10-04T15:44:58.476+0700: Total time for which application threads were stopped: 0,0000441 seconds, Stopping threads took: 0,0000068 seconds
2019-10-04T15:44:58.477+0700: Total time for which application threads were stopped: 0,0000446 seconds, Stopping threads took: 0,0000062 seconds
2019-10-04T15:44:58.477+0700: Total time for which application threads were stopped: 0,0000436 seconds, Stopping threads took: 0,0000065 seconds
2019-10-04T15:44:58.477+0700: Total time for which application threads were stopped: 0,0000599 seconds, Stopping threads took: 0,0000094 seconds
2019-10-04T15:44:58.480+0700: Total time for which application threads were stopped: 0,0001111 seconds, Stopping threads took: 0,0000190 seconds
2019-10-04T15:44:58.480+0700: Total time for which application threads were stopped: 0,0000827 seconds, Stopping threads took: 0,0000146 seconds
2019-10-04T15:44:58.484+0700: Total time for which application threads were stopped: 0,0000946 seconds, Stopping threads took: 0,0000169 seconds
2019-10-04T15:44:58.484+0700: Total time for which application threads were stopped: 0,0000713 seconds, Stopping threads took: 0,0000102 seconds
2019-10-04T15:44:58.492+0700: Total time for which application threads were stopped: 0,0000860 seconds, Stopping threads took: 0,0000139 seconds
2019-10-04T15:44:58.498+0700: Total time for which application threads were stopped: 0,0002550 seconds, Stopping threads took: 0,0000241 seconds
2019-10-04T15:44:58.507+0700: Total time for which application threads were stopped: 0,0000950 seconds, Stopping threads took: 0,0000139 seconds
2019-10-04T15:44:58.524+0700: Total time for which application threads were stopped: 0,0001138 seconds, Stopping threads took: 0,0000199 seconds
2019-10-04T15:44:58.524+0700: Total time for which application threads were stopped: 0,0000699 seconds, Stopping threads took: 0,0000083 seconds
2019-10-04T15:44:58.525+0700: Total time for which application threads were stopped: 0,0000567 seconds, Stopping threads took: 0,0000073 seconds
2019-10-04T15:44:58.525+0700: Total time for which application threads were stopped: 0,0000489 seconds, Stopping threads took: 0,0000078 seconds
2019-10-04T15:44:58.525+0700: Total time for which application threads were stopped: 0,0000436 seconds, Stopping threads took: 0,0000067 seconds
2019-10-04T15:44:58.525+0700: Total time for which application threads were stopped: 0,0000442 seconds, Stopping threads took: 0,0000075 seconds
2019-10-04T15:44:58.525+0700: Total time for which application threads were stopped: 0,0000502 seconds, Stopping threads took: 0,0000076 seconds
2019-10-04T15:44:58.531+0700: Total time for which application threads were stopped: 0,0000816 seconds, Stopping threads took: 0,0000155 seconds
2019-10-04T15:44:58.531+0700: Total time for which application threads were stopped: 0,0000837 seconds, Stopping threads took: 0,0000101 seconds
2019-10-04T15:44:58.531+0700: Total time for which application threads were stopped: 0,0000694 seconds, Stopping threads took: 0,0000101 seconds
2019-10-04T15:44:58.531+0700: Total time for which application threads were stopped: 0,0000532 seconds, Stopping threads took: 0,0000076 seconds
2019-10-04T15:44:58.531+0700: Total time for which application threads were stopped: 0,0001292 seconds, Stopping threads took: 0,0000142 seconds
2019-10-04T15:44:58.531+0700: Total time for which application threads were stopped: 0,0000458 seconds, Stopping threads took: 0,0000058 seconds
2019-10-04T15:44:58.532+0700: Total time for which application threads were stopped: 0,0000423 seconds, Stopping threads took: 0,0000075 seconds
[2019-10-04 15:44:58,559] INFO received request to whitelist topic null on mm  (com.uber.stream.kafka.mirrormaker.controller.rest.resources.TopicManagementRestletResource:118)
2019-10-04T15:44:58.562+0700: Total time for which application threads were stopped: 0,0001135 seconds, Stopping threads took: 0,0000151 seconds
[2019-10-04 15:44:59,091] INFO successuflly whitelist the topic null (com.uber.stream.kafka.mirrormaker.controller.rest.resources.TopicManagementRestletResource:168)
2019-10-04T15:44:59.096+0700: Total time for which application threads were stopped: 0,0001102 seconds, Stopping threads took: 0,0000163 seconds
2019-10-04T15:44:59.110+0700: Total time for which application threads were stopped: 0,0001227 seconds, Stopping threads took: 0,0000280 seconds
2019-10-04T15:44:59.111+0700: Total time for which application threads were stopped: 0,0000684 seconds, Stopping threads took: 0,0000091 seconds
2019-10-04T15:44:59.111+0700: Total time for which application threads were stopped: 0,0000767 seconds, Stopping threads took: 0,0000118 seconds
2019-10-04T15:44:59.130+0700: Total time for which application threads were stopped: 0,0001186 seconds, Stopping threads took: 0,0000165 seconds
[2019-10-04 15:44:59,366] INFO 17 START:INVOKE /uReplicatorDev/IDEALSTATES listener:org.apache.helix.controller.GenericHelixController (org.apache.helix.manager.zk.CallbackHandler:194)
[2019-10-04 15:44:59,367] INFO vid-dungnt95-u subscribes child-change. path: /uReplicatorDev/IDEALSTATES, listener: org.apache.helix.controller.GenericHelixController@11dc3715 (org.apache.helix.manager.zk.CallbackHandler:275)
[2019-10-04 15:44:59,662] INFO Subcribing to path:/uReplicatorDev/IDEALSTATES took:296 (org.apache.helix.manager.zk.CallbackHandler:356)
[2019-10-04 15:44:59,735] INFO START: Generic GenericClusterController.onIdealStateChange() (org.apache.helix.controller.GenericHelixController:402)
[2019-10-04 15:44:59,735] INFO END: GenericClusterController.onIdealStateChange() (org.apache.helix.controller.GenericHelixController:421)
[2019-10-04 15:44:59,736] INFO 17 END:INVOKE /uReplicatorDev/IDEALSTATES listener:org.apache.helix.controller.GenericHelixController Took: 370ms (org.apache.helix.manager.zk.CallbackHandler:266)
[2019-10-04 15:44:59,894] INFO START: Invoking controller pipeline for event: idealStateChange (org.apache.helix.controller.GenericHelixController:293)
[2019-10-04 15:44:59,894] INFO START ReadClusterDataStage.process() (org.apache.helix.controller.stages.ReadClusterDataStage:47)
[2019-10-04 15:44:59,894] INFO START: ClusterDataCache.refresh() (org.apache.helix.controller.stages.ClusterDataCache:90)
[2019-10-04 15:45:00,081] INFO END: ClusterDataCache.refresh(), took 187 ms (org.apache.helix.controller.stages.ClusterDataCache:229)
[2019-10-04 15:45:00,082] INFO END ReadClusterDataStage.process(). took: 188 ms (org.apache.helix.controller.stages.ReadClusterDataStage:94)
[2019-10-04 15:45:00,082] INFO START BestPossibleStateCalcStage.process() (org.apache.helix.controller.stages.BestPossibleStateCalcStage:51)
[2019-10-04 15:45:00,084] INFO Register MBean: ClusterStatus: cluster=uReplicatorDev,instanceName=testHelixMirrorMaker01,resourceName=topic_A (org.apache.helix.monitoring.mbeans.ClusterStatusMonitor:176)
[2019-10-04 15:45:00,084] INFO END BestPossibleStateCalcStage.process(). took: 2 ms (org.apache.helix.controller.stages.BestPossibleStateCalcStage:79)
[2019-10-04 15:45:00,085] INFO START TaskAssignmentStage.process() (org.apache.helix.controller.stages.TaskAssignmentStage:48)
[2019-10-04 15:45:00,085] INFO Sending Message f53312bc-b796-4fc2-9cdf-83960693c017 to testHelixMirrorMaker01 transit topic_A.0|[] from:OFFLINE to:ONLINE (org.apache.helix.controller.stages.TaskAssignmentStage:143)
[2019-10-04 15:45:00,110] INFO END TaskAssignmentStage.process(). took: 25 ms (org.apache.helix.controller.stages.TaskAssignmentStage:87)
[2019-10-04 15:45:00,110] INFO START PersistAssignmentStage.process() (org.apache.helix.controller.stages.PersistAssignmentStage:45)
[2019-10-04 15:45:00,110] INFO END: Invoking controller pipeline for event: idealStateChange, took 216 ms (org.apache.helix.controller.GenericHelixController:306)
2019-10-04T15:45:00.130+0700: Total time for which application threads were stopped: 0,0001307 seconds, Stopping threads took: 0,0000227 seconds
[2019-10-04 15:45:00,156] INFO 17 START:INVOKE /uReplicatorDev/INSTANCES/testHelixMirrorMaker01/MESSAGES listener:org.apache.helix.controller.GenericHelixController (org.apache.helix.manager.zk.CallbackHandler:194)
[2019-10-04 15:45:00,156] INFO vid-dungnt95-u subscribes child-change. path: /uReplicatorDev/INSTANCES/testHelixMirrorMaker01/MESSAGES, listener: org.apache.helix.controller.GenericHelixController@11dc3715 (org.apache.helix.manager.zk.CallbackHandler:275)
[2019-10-04 15:45:00,202] INFO Subcribing to path:/uReplicatorDev/INSTANCES/testHelixMirrorMaker01/MESSAGES took:46 (org.apache.helix.manager.zk.CallbackHandler:356)
[2019-10-04 15:45:00,256] INFO START: GenericClusterController.onMessage() (org.apache.helix.controller.GenericHelixController:332)
[2019-10-04 15:45:00,256] INFO END: GenericClusterController.onMessage() (org.apache.helix.controller.GenericHelixController:348)
[2019-10-04 15:45:00,256] INFO 17 END:INVOKE /uReplicatorDev/INSTANCES/testHelixMirrorMaker01/MESSAGES listener:org.apache.helix.controller.GenericHelixController Took: 100ms (org.apache.helix.manager.zk.CallbackHandler:266)
[2019-10-04 15:45:00,387] INFO 17 START:INVOKE /uReplicatorDev/INSTANCES/testHelixMirrorMaker01/CURRENTSTATES/1000000cfa00044 listener:org.apache.helix.controller.GenericHelixController (org.apache.helix.manager.zk.CallbackHandler:194)
[2019-10-04 15:45:00,387] INFO vid-dungnt95-u subscribes child-change. path: /uReplicatorDev/INSTANCES/testHelixMirrorMaker01/CURRENTSTATES/1000000cfa00044, listener: org.apache.helix.controller.GenericHelixController@11dc3715 (org.apache.helix.manager.zk.CallbackHandler:275)
[2019-10-04 15:45:00,654] INFO START: Invoking controller pipeline for event: messageChange (org.apache.helix.controller.GenericHelixController:293)
[2019-10-04 15:45:00,654] INFO START ReadClusterDataStage.process() (org.apache.helix.controller.stages.ReadClusterDataStage:47)
[2019-10-04 15:45:00,654] INFO START: ClusterDataCache.refresh() (org.apache.helix.controller.stages.ClusterDataCache:90)
[2019-10-04 15:45:00,881] INFO Subcribing to path:/uReplicatorDev/INSTANCES/testHelixMirrorMaker01/CURRENTSTATES/1000000cfa00044 took:494 (org.apache.helix.manager.zk.CallbackHandler:356)
[2019-10-04 15:45:00,904] INFO END: ClusterDataCache.refresh(), took 249 ms (org.apache.helix.controller.stages.ClusterDataCache:229)
[2019-10-04 15:45:00,905] INFO END ReadClusterDataStage.process(). took: 251 ms (org.apache.helix.controller.stages.ReadClusterDataStage:94)
[2019-10-04 15:45:00,905] INFO START BestPossibleStateCalcStage.process() (org.apache.helix.controller.stages.BestPossibleStateCalcStage:51)
[2019-10-04 15:45:00,906] INFO END BestPossibleStateCalcStage.process(). took: 1 ms (org.apache.helix.controller.stages.BestPossibleStateCalcStage:79)
[2019-10-04 15:45:00,906] INFO START TaskAssignmentStage.process() (org.apache.helix.controller.stages.TaskAssignmentStage:48)
[2019-10-04 15:45:00,906] INFO END TaskAssignmentStage.process(). took: 0 ms (org.apache.helix.controller.stages.TaskAssignmentStage:87)
[2019-10-04 15:45:00,906] INFO START PersistAssignmentStage.process() (org.apache.helix.controller.stages.PersistAssignmentStage:45)
[2019-10-04 15:45:00,907] INFO END: Invoking controller pipeline for event: messageChange, took 253 ms (org.apache.helix.controller.GenericHelixController:306)
[2019-10-04 15:45:00,928] INFO START: GenericClusterController.onStateChange() (org.apache.helix.controller.GenericHelixController:316)
[2019-10-04 15:45:00,928] INFO END: GenericClusterController.onStateChange() (org.apache.helix.controller.GenericHelixController:326)
[2019-10-04 15:45:00,928] INFO 17 END:INVOKE /uReplicatorDev/INSTANCES/testHelixMirrorMaker01/CURRENTSTATES/1000000cfa00044 listener:org.apache.helix.controller.GenericHelixController Took: 541ms (org.apache.helix.manager.zk.CallbackHandler:266)
[2019-10-04 15:45:00,975] INFO 17 START:INVOKE /uReplicatorDev/INSTANCES/testHelixMirrorMaker01/CURRENTSTATES/1000000cfa00044 listener:org.apache.helix.controller.GenericHelixController (org.apache.helix.manager.zk.CallbackHandler:194)
[2019-10-04 15:45:00,975] INFO vid-dungnt95-u subscribes child-change. path: /uReplicatorDev/INSTANCES/testHelixMirrorMaker01/CURRENTSTATES/1000000cfa00044, listener: org.apache.helix.controller.GenericHelixController@11dc3715 (org.apache.helix.manager.zk.CallbackHandler:275)
2019-10-04T15:45:01.131+0700: Total time for which application threads were stopped: 0,0001216 seconds, Stopping threads took: 0,0000200 seconds
[2019-10-04 15:45:01,214] INFO START: Invoking controller pipeline for event: currentStateChange (org.apache.helix.controller.GenericHelixController:293)
[2019-10-04 15:45:01,215] INFO START ReadClusterDataStage.process() (org.apache.helix.controller.stages.ReadClusterDataStage:47)
[2019-10-04 15:45:01,215] INFO START: ClusterDataCache.refresh() (org.apache.helix.controller.stages.ClusterDataCache:90)
[2019-10-04 15:45:01,446] INFO Subcribing to path:/uReplicatorDev/INSTANCES/testHelixMirrorMaker01/CURRENTSTATES/1000000cfa00044 took:471 (org.apache.helix.manager.zk.CallbackHandler:356)
[2019-10-04 15:45:01,447] INFO END: ClusterDataCache.refresh(), took 232 ms (org.apache.helix.controller.stages.ClusterDataCache:229)
[2019-10-04 15:45:01,447] INFO END ReadClusterDataStage.process(). took: 232 ms (org.apache.helix.controller.stages.ReadClusterDataStage:94)
[2019-10-04 15:45:01,448] INFO START BestPossibleStateCalcStage.process() (org.apache.helix.controller.stages.BestPossibleStateCalcStage:51)
[2019-10-04 15:45:01,451] INFO END BestPossibleStateCalcStage.process(). took: 3 ms (org.apache.helix.controller.stages.BestPossibleStateCalcStage:79)
[2019-10-04 15:45:01,453] INFO START TaskAssignmentStage.process() (org.apache.helix.controller.stages.TaskAssignmentStage:48)
[2019-10-04 15:45:01,453] INFO END TaskAssignmentStage.process(). took: 0 ms (org.apache.helix.controller.stages.TaskAssignmentStage:87)
[2019-10-04 15:45:01,453] INFO START PersistAssignmentStage.process() (org.apache.helix.controller.stages.PersistAssignmentStage:45)
[2019-10-04 15:45:01,453] INFO START ExternalViewComputeStage.process() (org.apache.helix.controller.stages.ExternalViewComputeStage:59)
[2019-10-04 15:45:01,503] INFO START: GenericClusterController.onStateChange() (org.apache.helix.controller.GenericHelixController:316)
[2019-10-04 15:45:01,504] INFO END: GenericClusterController.onStateChange() (org.apache.helix.controller.GenericHelixController:326)
[2019-10-04 15:45:01,504] INFO 17 END:INVOKE /uReplicatorDev/INSTANCES/testHelixMirrorMaker01/CURRENTSTATES/1000000cfa00044 listener:org.apache.helix.controller.GenericHelixController Took: 529ms (org.apache.helix.manager.zk.CallbackHandler:266)
[2019-10-04 15:45:01,523] INFO Register MBean: ClusterStatus: cluster=uReplicatorDev,resourceName=topic_A (org.apache.helix.monitoring.mbeans.ClusterStatusMonitor:176)
[2019-10-04 15:45:01,559] INFO 17 START:INVOKE /uReplicatorDev/INSTANCES/testHelixMirrorMaker01/MESSAGES listener:org.apache.helix.controller.GenericHelixController (org.apache.helix.manager.zk.CallbackHandler:194)
[2019-10-04 15:45:01,559] INFO vid-dungnt95-u subscribes child-change. path: /uReplicatorDev/INSTANCES/testHelixMirrorMaker01/MESSAGES, listener: org.apache.helix.controller.GenericHelixController@11dc3715 (org.apache.helix.manager.zk.CallbackHandler:275)
[2019-10-04 15:45:01,584] INFO END ExternalViewComputeStage.process(). took: 131 ms (org.apache.helix.controller.stages.ExternalViewComputeStage:185)
[2019-10-04 15:45:01,584] INFO END: Invoking controller pipeline for event: currentStateChange, took 369 ms (org.apache.helix.controller.GenericHelixController:306)
[2019-10-04 15:45:01,618] INFO Subcribing to path:/uReplicatorDev/INSTANCES/testHelixMirrorMaker01/MESSAGES took:59 (org.apache.helix.manager.zk.CallbackHandler:356)
[2019-10-04 15:45:01,645] INFO START: GenericClusterController.onMessage() (org.apache.helix.controller.GenericHelixController:332)
[2019-10-04 15:45:01,645] INFO END: GenericClusterController.onMessage() (org.apache.helix.controller.GenericHelixController:348)
[2019-10-04 15:45:01,645] INFO 17 END:INVOKE /uReplicatorDev/INSTANCES/testHelixMirrorMaker01/MESSAGES listener:org.apache.helix.controller.GenericHelixController Took: 86ms (org.apache.helix.manager.zk.CallbackHandler:266)
[2019-10-04 15:45:01,747] INFO START: Invoking controller pipeline for event: currentStateChange (org.apache.helix.controller.GenericHelixController:293)
[2019-10-04 15:45:01,747] INFO START ReadClusterDataStage.process() (org.apache.helix.controller.stages.ReadClusterDataStage:47)
[2019-10-04 15:45:01,747] INFO START: ClusterDataCache.refresh() (org.apache.helix.controller.stages.ClusterDataCache:90)
[2019-10-04 15:45:01,938] INFO END: ClusterDataCache.refresh(), took 191 ms (org.apache.helix.controller.stages.ClusterDataCache:229)
[2019-10-04 15:45:01,938] INFO END ReadClusterDataStage.process(). took: 191 ms (org.apache.helix.controller.stages.ReadClusterDataStage:94)
[2019-10-04 15:45:01,939] INFO START BestPossibleStateCalcStage.process() (org.apache.helix.controller.stages.BestPossibleStateCalcStage:51)
[2019-10-04 15:45:01,943] INFO END BestPossibleStateCalcStage.process(). took: 4 ms (org.apache.helix.controller.stages.BestPossibleStateCalcStage:79)
[2019-10-04 15:45:01,943] INFO START TaskAssignmentStage.process() (org.apache.helix.controller.stages.TaskAssignmentStage:48)
[2019-10-04 15:45:01,944] INFO END TaskAssignmentStage.process(). took: 1 ms (org.apache.helix.controller.stages.TaskAssignmentStage:87)
[2019-10-04 15:45:01,944] INFO START PersistAssignmentStage.process() (org.apache.helix.controller.stages.PersistAssignmentStage:45)
[2019-10-04 15:45:01,944] INFO START ExternalViewComputeStage.process() (org.apache.helix.controller.stages.ExternalViewComputeStage:59)
[2019-10-04 15:45:01,998] INFO END ExternalViewComputeStage.process(). took: 54 ms (org.apache.helix.controller.stages.ExternalViewComputeStage:185)
[2019-10-04 15:45:01,999] INFO END: Invoking controller pipeline for event: currentStateChange, took 252 ms (org.apache.helix.controller.GenericHelixController:306)
[2019-10-04 15:45:02,124] INFO START: Invoking controller pipeline for event: messageChange (org.apache.helix.controller.GenericHelixController:293)
[2019-10-04 15:45:02,124] INFO START ReadClusterDataStage.process() (org.apache.helix.controller.stages.ReadClusterDataStage:47)
[2019-10-04 15:45:02,124] INFO START: ClusterDataCache.refresh() (org.apache.helix.controller.stages.ClusterDataCache:90)
2019-10-04T15:45:02.131+0700: Total time for which application threads were stopped: 0,0001280 seconds, Stopping threads took: 0,0000221 seconds
[2019-10-04 15:45:02,359] INFO END: ClusterDataCache.refresh(), took 234 ms (org.apache.helix.controller.stages.ClusterDataCache:229)
[2019-10-04 15:45:02,360] INFO END ReadClusterDataStage.process(). took: 236 ms (org.apache.helix.controller.stages.ReadClusterDataStage:94)
[2019-10-04 15:45:02,361] INFO START BestPossibleStateCalcStage.process() (org.apache.helix.controller.stages.BestPossibleStateCalcStage:51)
[2019-10-04 15:45:02,363] INFO END BestPossibleStateCalcStage.process(). took: 2 ms (org.apache.helix.controller.stages.BestPossibleStateCalcStage:79)
[2019-10-04 15:45:02,364] INFO START TaskAssignmentStage.process() (org.apache.helix.controller.stages.TaskAssignmentStage:48)
[2019-10-04 15:45:02,364] INFO END TaskAssignmentStage.process(). took: 0 ms (org.apache.helix.controller.stages.TaskAssignmentStage:87)
[2019-10-04 15:45:02,364] INFO START PersistAssignmentStage.process() (org.apache.helix.controller.stages.PersistAssignmentStage:45)
[2019-10-04 15:45:02,364] INFO END: Invoking controller pipeline for event: messageChange, took 240 ms (org.apache.helix.controller.GenericHelixController:306)
2019-10-04T15:45:03.131+0700: Total time for which application threads were stopped: 0,0002871 seconds, Stopping threads took: 0,0000465 seconds

Log on Worker : 

[2019-10-04 15:45:00,151] INFO 21 START:INVOKE /uReplicatorDev/INSTANCES/testHelixMirrorMaker01/MESSAGES listener:org.apache.helix.messaging.handling.HelixTaskExecutor (org.apache.helix.manager.zk.CallbackHandler:194)
[2019-10-04 15:45:00,152] INFO testHelixMirrorMaker01 subscribes child-change. path: /uReplicatorDev/INSTANCES/testHelixMirrorMaker01/MESSAGES, listener: org.apache.helix.messaging.handling.HelixTaskExecutor@485966cc (org.apache.helix.manager.zk.CallbackHandler:275)
[2019-10-04 15:45:00,197] INFO Subcribing to path:/uReplicatorDev/INSTANCES/testHelixMirrorMaker01/MESSAGES took:45 (org.apache.helix.manager.zk.CallbackHandler:356)
2019-10-04T15:45:00.249+0700: Total time for which application threads were stopped: 0,0001380 seconds, Stopping threads took: 0,0000267 seconds
[2019-10-04 15:45:00,631] INFO Scheduling message: f53312bc-b796-4fc2-9cdf-83960693c017 (org.apache.helix.messaging.handling.HelixTaskExecutor:355)
[2019-10-04 15:45:00,633] INFO Submit task: f53312bc-b796-4fc2-9cdf-83960693c017 to pool: java.util.concurrent.ThreadPoolExecutor@2c35e847[Running, pool size = 6, active threads = 0, queued tasks = 0, completed tasks = 6] (org.apache.helix.messaging.handling.HelixTaskExecutor:370)
[2019-10-04 15:45:00,634] INFO Message: f53312bc-b796-4fc2-9cdf-83960693c017 handling task scheduled (org.apache.helix.messaging.handling.HelixTaskExecutor:385)
[2019-10-04 15:45:00,634] INFO 21 END:INVOKE /uReplicatorDev/INSTANCES/testHelixMirrorMaker01/MESSAGES listener:org.apache.helix.messaging.handling.HelixTaskExecutor Took: 483ms (org.apache.helix.manager.zk.CallbackHandler:266)
[2019-10-04 15:45:00,636] INFO handling task: f53312bc-b796-4fc2-9cdf-83960693c017 begin, at: 1570178700636 (org.apache.helix.messaging.handling.HelixTask:70)
[2019-10-04 15:45:00,663] INFO Merging with delta list, recordId = topic_A other:topic_A (org.apache.helix.ZNRecord:491)
[2019-10-04 15:45:00,691] INFO Instance testHelixMirrorMaker01, partition 0 received state transition from OFFLINE to ONLINE on session 1000000cfa00044. (org.apache.helix.messaging.handling.HelixStateTransitionHandler:337)
[2019-10-04 15:45:00,691] INFO OnlineOfflineStateModel.onBecomeOnlineFromOffline for topic: topic_A, partition: 0 to instance: testHelixMirrorMaker01 (kafka.mirrormaker.HelixWorkerOnlineOfflineStateModelFactory:66)
[2019-10-04 15:45:00,691] INFO Adding topic: topic_A , partition 0 (kafka.mirrormaker.KafkaConnector:66)
[2019-10-04 15:45:00,720] INFO Fetched offset : -1, for topic: topic_A , partition 0 (kafka.mirrormaker.KafkaConnector:66)
[2019-10-04 15:45:00,720] INFO [CompactConsumerFetcherManager-1570178225604] adding new topic-partition topic_A - 0 (kafka.mirrormaker.CompactConsumerFetcherManager:66)
[2019-10-04 15:45:00,810] INFO Message f53312bc-b796-4fc2-9cdf-83960693c017 completed. (org.apache.helix.messaging.handling.HelixTask:115)
[2019-10-04 15:45:00,829] INFO [kloak-mirrormaker-test_kloakmms01-sjc1-leader-finder-thread]: Partitions without leader Set(topic_A-0) (kafka.mirrormaker.CompactConsumerFetcherManager$LeaderFinderThread:66)
[2019-10-04 15:45:00,836] INFO Registering bean: Cluster=uReplicatorDev,Resource=topic_A,Transition=OFFLINE--ONLINE (org.apache.helix.monitoring.ParticipantStatusMonitor:109)
[2019-10-04 15:45:00,837] INFO message finished: f53312bc-b796-4fc2-9cdf-83960693c017, took 196 (org.apache.helix.messaging.handling.HelixTaskExecutor:448)
[2019-10-04 15:45:00,837] INFO msg: f53312bc-b796-4fc2-9cdf-83960693c017 handling task completed, results:true, at: 1570178700837, took:201 (org.apache.helix.messaging.handling.HelixTask:170)
[2019-10-04 15:45:00,883] INFO 21 START:INVOKE /uReplicatorDev/INSTANCES/testHelixMirrorMaker01/MESSAGES listener:org.apache.helix.messaging.handling.HelixTaskExecutor (org.apache.helix.manager.zk.CallbackHandler:194)
[2019-10-04 15:45:00,883] INFO testHelixMirrorMaker01 subscribes child-change. path: /uReplicatorDev/INSTANCES/testHelixMirrorMaker01/MESSAGES, listener: org.apache.helix.messaging.handling.HelixTaskExecutor@485966cc (org.apache.helix.manager.zk.CallbackHandler:275)
[2019-10-04 15:45:00,915] INFO Verifying properties (kafka.utils.VerifiableProperties:66)
[2019-10-04 15:45:00,915] INFO Property client.id is overridden to kloak-mirrormaker-test (kafka.utils.VerifiableProperties:66)
[2019-10-04 15:45:00,916] INFO Property metadata.broker.list is overridden to source_cluster1:9092,source_cluster2:9092 (kafka.utils.VerifiableProperties:66)
[2019-10-04 15:45:00,916] INFO Property request.timeout.ms is overridden to 30000 (kafka.utils.VerifiableProperties:66)
[2019-10-04 15:45:00,917] INFO Fetching metadata from broker BrokerEndPoint(1,source_cluster1,9092) with correlation id 2 for 1 topic(s) Set(topic_A) (kafka.client.ClientUtils$:66)
2019-10-04T15:45:00.918+0700: Total time for which application threads were stopped: 0,0002558 seconds, Stopping threads took: 0,0000209 seconds
[2019-10-04 15:45:00,930] INFO Subcribing to path:/uReplicatorDev/INSTANCES/testHelixMirrorMaker01/MESSAGES took:47 (org.apache.helix.manager.zk.CallbackHandler:356)
[2019-10-04 15:45:00,940] INFO Connected to source_cluster1:9092 for producing (kafka.producer.SyncProducer:66)
[2019-10-04 15:45:00,953] INFO No Messages to process (org.apache.helix.messaging.handling.HelixTaskExecutor:619)
[2019-10-04 15:45:00,953] INFO 21 END:INVOKE /uReplicatorDev/INSTANCES/testHelixMirrorMaker01/MESSAGES listener:org.apache.helix.messaging.handling.HelixTaskExecutor Took: 70ms (org.apache.helix.manager.zk.CallbackHandler:266)
[2019-10-04 15:45:00,966] INFO Disconnecting from source_cluster1:9092 (kafka.producer.SyncProducer:66)
[2019-10-04 15:45:00,967] INFO [kloak-mirrormaker-test_kloakmms01-sjc1-leader-finder-thread]: Try find leader for topic: topic_A, partition:0 (kafka.mirrormaker.CompactConsumerFetcherManager$LeaderFinderThread:66)
[2019-10-04 15:45:00,967] INFO [kloak-mirrormaker-test_kloakmms01-sjc1-leader-finder-thread]: Find leader for partitions finished, took: 138 ms (kafka.mirrormaker.CompactConsumerFetcherManager$LeaderFinderThread:66)
2019-10-04T15:45:00.969+0700: Total time for which application threads were stopped: 0,0001709 seconds, Stopping threads took: 0,0000241 seconds
2019-10-04T15:45:01.211+0700: Total time for which application threads were stopped: 0,0001274 seconds, Stopping threads took: 0,0000177 seconds
2019-10-04T15:45:01.212+0700: Total time for which application threads were stopped: 0,0001252 seconds, Stopping threads took: 0,0000162 seconds
2019-10-04T15:45:01.212+0700: Total time for which application threads were stopped: 0,0000881 seconds, Stopping threads took: 0,0000125 seconds
2019-10-04T15:45:01.212+0700: Total time for which application threads were stopped: 0,0000585 seconds, Stopping threads took: 0,0000076 seconds
2019-10-04T15:45:01.212+0700: Total time for which application threads were stopped: 0,0000667 seconds, Stopping threads took: 0,0000088 seconds
2019-10-04T15:45:01.233+0700: Total time for which application threads were stopped: 0,0001660 seconds, Stopping threads took: 0,0000264 seconds
2019-10-04T15:45:01.234+0700: Total time for which application threads were stopped: 0,0001620 seconds, Stopping threads took: 0,0000285 seconds
2019-10-04T15:45:01.235+0700: Total time for which application threads were stopped: 0,0001550 seconds, Stopping threads took: 0,0000221 seconds
2019-10-04T15:45:01.241+0700: Total time for which application threads were stopped: 0,0001180 seconds, Stopping threads took: 0,0000155 seconds
[2019-10-04 15:45:01,241] INFO [CompactConsumerFetcherManager-1570178225604] Fetcher Thread for topic partitions: ArrayBuffer([topic_A-0, InitialOffset -1] ) is CompactConsumerFetcherThread-kloak-mirrormaker-test_kloakmms01-sjc1-0-1 (kafka.mirrormaker.CompactConsumerFetcherManager:66)
[2019-10-04 15:45:01,242] INFO [CompactConsumerFetcherManager-1570178225604] Added fetcher for partitions ArrayBuffer([topic_A-0, initOffset -1 to broker BrokerEndPoint(1,source_cluster1,9092)] ) (kafka.mirrormaker.CompactConsumerFetcherManager:66)
2019-10-04T15:45:01.310+0700: Total time for which application threads were stopped: 0,0001268 seconds, Stopping threads took: 0,0000223 seconds
[2019-10-04 15:45:01,462] WARN [Producer clientId=kloak-mirrormaker-test] Error while fetching metadata with correlation id 17 : {topic_A=LEADER_NOT_AVAILABLE} (org.apache.kafka.clients.NetworkClient:882)
2019-10-04T15:45:01.602+0700: Total time for which application threads were stopped: 0,0001947 seconds, Stopping threads took: 0,0000654 seconds
2019-10-04T15:45:02.603+0700: Total time for which application threads were stopped: 0,0001921 seconds, Stopping threads took: 0,0000587 seconds
2019-10-04T15:45:03.603+0700: Total time for which application threads were stopped: 0,0001009 seconds, Stopping threads took: 0,0000183 seconds
2019-10-04T15:45:04.603+0700: Total time for which application threads were stopped: 0,0001194 seconds, Stopping threads took: 0,0000215 seconds
2019-10-04T15:45:06.604+0700: Total time for which application threads were stopped: 0,0002853 seconds, Stopping threads took: 0,0000452 seconds
2019-10-04T15:45:08.604+0700: Total time for which application threads were stopped: 0,0001599 seconds, Stopping threads took: 0,0000260 seconds
2019-10-04T15:45:09.604+0700: Total time for which application threads were stopped: 0,0001176 seconds, Stopping threads took: 0,0000198 seconds
2019-10-04T15:45:11.606+0700: Total time for which application threads were stopped: 0,0001304 seconds, Stopping threads took: 0,0000223 seconds

Result : On destination Cluster : Have new topic name in the same Cluster topic_A with all message from Source Cluster for example : Source Cluster have 100message -> Destination Cluster topic_A created with 100 message -> auto.offset.reset=smallest worked !!

Step4 : use provider send new message to topic_A in Source Cluster Result : message include both of topic in Source Cluster + Destination Cluster Source cluster : 101 message Destination cluster : 101 message Dont have topic : new_topic_A in Destination Cluster as expected.

Step5 : shutdown Controller & Worker And Start it again, send 3 new message to topic in Source cluster Log of worker : 

2019-10-04T16:30:49.531+0700: Total time for which application threads were stopped: 0,0003614 seconds, Stopping threads took: 0,0000113 seconds
2019-10-04T16:30:49.811+0700: Total time for which application threads were stopped: 0,0002192 seconds, Stopping threads took: 0,0000489 seconds
[2019-10-04 16:30:49,881] WARN [Producer clientId=kloak-mirrormaker-test] Error while fetching metadata with correlation id 2 : {new_topic_A=LEADER_NOT_AVAILABLE} (org.apache.kafka.clients.NetworkClient:882)
[2019-10-04 16:30:49,881] INFO Cluster ID: fUDG1wLqQDO5b7bHA-PwXw (org.apache.kafka.clients.Metadata:265)
2019-10-04T16:30:50.236+0700: Total time for which application threads were stopped: 0,0001161 seconds, Stopping threads took: 0,0000210 seconds
2019-10-04T16:30:51.236+0700: Total time for which application threads were stopped: 0,0003000 seconds, Stopping threads took: 0,0002062 seconds

Result : New topic : new_topic_A created in Destination cluster Message :

Question is : How can I replicate all message in topic_A( Source cluster ) to new_topic_A(Destination cluster) ( topic : topic_A & new_topic_A automatically create in Destination cluster )

dungnt081191 commented 5 years ago

@xhl1988 Can you clarify the process and properties for me ?

yangy0000 commented 5 years ago

Did you specify topicmapping.properties on step 3 ?

dungnt081191 commented 5 years ago

hi @yangy0000 , yes, i specify it , add/remove/update topic source & destination . UPDATE : I think i found the issue : The process will be : 1 - start controller 2 - start worker 3 - If modified topicmapping.properties - MUST restart worker 4 - send HTTP REQUEST manually 5 - check the result : work as expected : all message from source cluster will be replicated to destination clustes with exactly name specify in topicmapping.properties

Thank you !