Hey,
so I turned on debug logging and now I see the MM2 does a lot, so it is
hard to tell exactly what :D
So, what I see the most during that "not mirroring messages" period is logs
about:
- [AdminClient clientId=adminclient-31] Queueing
Call(callName=findCoordinator, deadlineMs=1584976266682) with a timeout
120000 ms from now.
- [AdminClient clientId=adminclient-31] Queueing
Call(callName=listConsumerGroupOffsets, deadlineMs=1584976267162) with a
timeout 119999 ms from now.
- [AdminClient clientId=adminclient-31] Using older server API v1 to send
FIND_COORDINATOR {key=aaaaabdd997ddhfb8d,key_type=0} with correlation id
1473 to node 1004 (org.apache.kafka.clients.NetworkClient)
- [AdminClient clientId=adminclient-31] Using older server API v3 to send
OFFSET_FETCH {group_id=vvvvvvvvvv586499b754vctp8,topics=null} with
correlation id 1062 to node 1006
- [Consumer clientId=consumer-19, groupId=null] Added READ_UNCOMMITTED
fetch request for partition mm2-offset-syncs.backup.internal-0 at position
FetchPosition{offset=5187531, offsetEpoch=Optional[0],
currentLeader=LeaderAndEpoch ...
- [Consumer clientId=consumer-19, groupId=null] Sending READ_UNCOMMITTED
IncrementalFetchRequest(toSend=(), toForget=(),
implied=(mm2-offset-syncs.backup.internal-0)) to broker ...
- [Consumer clientId=consumer-19, groupId=null] Using older server API v7
to send FETCH
{replica_id=-1,max_wait_time=500,min_bytes=1,max_bytes=52428800, ...
- [Consumer clientId=consumer-21, groupId=null] Sending READ_UNCOMMITTED
IncrementalFetchRequest(toSend=(), toForget=(),
implied=(mm2-offset-syncs.backup.internal-0)) to broker 172.x.y.z:9092 (id:
1004 ...
I can share the full log if that helps.
Peter
On Fri, 20 Mar 2020 at 17:52, Ryanne Dolan <ryannedo...@gmail.com> wrote:
> Hmm, maybe turn on debugging info and try to figure out what Connect is
> doing during that time.
>
> Ryanne
>
> On Fri, Mar 20, 2020 at 6:15 AM Péter Sinóros-Szabó
> <peter.sinoros-sz...@transferwise.com.invalid> wrote:
>
> > Hi,
> >
> > I don't have the previous logs, so I restarted MM2, that produces the
> same
> > results. So new logs:
> >
> > MM2 starts and seems to be ready, but not mirroring message:
> > [2020-03-20 10:50:11,985] INFO [Producer
> > clientId=connector-producer-MirrorCheckpointConnector-0] Cluster ID:
> > 700ZEsu0ShuzPZ6lZE54_Q (org.apache.kafka.clients.Metadata)
> > [2020-03-20 10:50:19,927] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Committing offsets
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> >
> > It takes another 5 minutes of just the usually "committing offsets" kinda
> > messages (these are all the logs MM2 prints at that time)
> > [2020-03-20 10:50:19,927] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Committing offsets
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:50:19,927] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} flushing 0 outstanding
> > messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:50:19,936] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Finished commitOffsets
> > successfully in 9 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:50:57,634] INFO
> WorkerSourceTask{id=MirrorSourceConnector-1}
> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:50:57,635] INFO
> WorkerSourceTask{id=MirrorSourceConnector-1}
> > flushing 0 outstanding messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:50:57,636] INFO
> WorkerSourceTask{id=MirrorSourceConnector-2}
> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:50:57,636] INFO
> WorkerSourceTask{id=MirrorSourceConnector-2}
> > flushing 0 outstanding messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:50:57,638] INFO
> WorkerSourceTask{id=MirrorSourceConnector-0}
> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:50:57,638] INFO
> WorkerSourceTask{id=MirrorSourceConnector-0}
> > flushing 0 outstanding messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:50:57,638] INFO
> WorkerSourceTask{id=MirrorSourceConnector-3}
> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:50:57,638] INFO
> WorkerSourceTask{id=MirrorSourceConnector-3}
> > flushing 0 outstanding messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:50:57,639] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Committing offsets
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:50:57,639] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} flushing 0 outstanding
> > messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:50:57,650] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Finished commitOffsets
> > successfully in 11 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:51:11,886] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-1} Committing offsets
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:51:11,886] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-1} flushing 0 outstanding
> > messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:51:11,886] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-2} Committing offsets
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:51:11,886] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-2} flushing 0 outstanding
> > messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:51:11,886] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-3} Committing offsets
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:51:11,886] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-3} flushing 0 outstanding
> > messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:51:11,887] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-0} Committing offsets
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:51:11,887] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-0} flushing 0 outstanding
> > messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:51:19,936] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Committing offsets
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:51:19,936] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} flushing 0 outstanding
> > messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:51:19,941] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Finished commitOffsets
> > successfully in 5 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:51:57,635] INFO
> WorkerSourceTask{id=MirrorSourceConnector-1}
> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:51:57,635] INFO
> WorkerSourceTask{id=MirrorSourceConnector-1}
> > flushing 0 outstanding messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:51:57,636] INFO
> WorkerSourceTask{id=MirrorSourceConnector-2}
> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:51:57,636] INFO
> WorkerSourceTask{id=MirrorSourceConnector-2}
> > flushing 0 outstanding messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:51:57,638] INFO
> WorkerSourceTask{id=MirrorSourceConnector-0}
> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:51:57,638] INFO
> WorkerSourceTask{id=MirrorSourceConnector-0}
> > flushing 0 outstanding messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:51:57,639] INFO
> WorkerSourceTask{id=MirrorSourceConnector-3}
> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:51:57,639] INFO
> WorkerSourceTask{id=MirrorSourceConnector-3}
> > flushing 0 outstanding messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:51:57,651] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Committing offsets
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:51:57,651] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} flushing 0 outstanding
> > messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:51:57,658] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Finished commitOffsets
> > successfully in 7 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:52:11,886] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-1} Committing offsets
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:52:11,886] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-1} flushing 0 outstanding
> > messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:52:11,933] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-1} Finished commitOffsets
> > successfully in 47 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:52:11,933] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-2} Committing offsets
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:52:11,933] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-2} flushing 0 outstanding
> > messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:52:11,965] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-2} Finished commitOffsets
> > successfully in 32 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:52:11,965] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-3} Committing offsets
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:52:11,965] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-3} flushing 0 outstanding
> > messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:52:11,997] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-3} Finished commitOffsets
> > successfully in 32 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:52:11,997] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-0} Committing offsets
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:52:11,997] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-0} flushing 0 outstanding
> > messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:52:12,026] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-0} Finished commitOffsets
> > successfully in 29 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:52:19,941] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Committing offsets
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:52:19,941] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} flushing 0 outstanding
> > messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:52:19,946] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Finished commitOffsets
> > successfully in 5 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:52:57,635] INFO
> WorkerSourceTask{id=MirrorSourceConnector-1}
> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:52:57,635] INFO
> WorkerSourceTask{id=MirrorSourceConnector-1}
> > flushing 0 outstanding messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:52:57,637] INFO
> WorkerSourceTask{id=MirrorSourceConnector-2}
> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:52:57,637] INFO
> WorkerSourceTask{id=MirrorSourceConnector-2}
> > flushing 0 outstanding messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:52:57,638] INFO
> WorkerSourceTask{id=MirrorSourceConnector-0}
> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:52:57,638] INFO
> WorkerSourceTask{id=MirrorSourceConnector-0}
> > flushing 0 outstanding messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:52:57,639] INFO
> WorkerSourceTask{id=MirrorSourceConnector-3}
> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:52:57,639] INFO
> WorkerSourceTask{id=MirrorSourceConnector-3}
> > flushing 0 outstanding messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:52:57,658] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Committing offsets
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:52:57,658] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} flushing 0 outstanding
> > messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:52:57,666] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Finished commitOffsets
> > successfully in 8 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:53:11,933] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-1} Committing offsets
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:53:11,933] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-1} flushing 0 outstanding
> > messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:53:11,988] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-1} Finished commitOffsets
> > successfully in 55 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:53:11,988] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-2} Committing offsets
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:53:11,988] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-2} flushing 0 outstanding
> > messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:53:12,027] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-2} Finished commitOffsets
> > successfully in 39 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:53:12,027] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-3} Committing offsets
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:53:12,027] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-3} flushing 0 outstanding
> > messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:53:12,067] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-3} Finished commitOffsets
> > successfully in 40 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:53:12,067] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-0} Committing offsets
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:53:12,067] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-0} flushing 0 outstanding
> > messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:53:12,102] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-0} Finished commitOffsets
> > successfully in 35 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:53:19,946] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Committing offsets
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:53:19,946] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} flushing 0 outstanding
> > messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:53:19,950] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Finished commitOffsets
> > successfully in 4 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:53:57,636] INFO
> WorkerSourceTask{id=MirrorSourceConnector-1}
> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:53:57,636] INFO
> WorkerSourceTask{id=MirrorSourceConnector-1}
> > flushing 0 outstanding messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:53:57,637] INFO
> WorkerSourceTask{id=MirrorSourceConnector-2}
> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:53:57,637] INFO
> WorkerSourceTask{id=MirrorSourceConnector-2}
> > flushing 0 outstanding messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:53:57,638] INFO
> WorkerSourceTask{id=MirrorSourceConnector-0}
> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:53:57,638] INFO
> WorkerSourceTask{id=MirrorSourceConnector-0}
> > flushing 0 outstanding messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:53:57,639] INFO
> WorkerSourceTask{id=MirrorSourceConnector-3}
> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:53:57,639] INFO
> WorkerSourceTask{id=MirrorSourceConnector-3}
> > flushing 0 outstanding messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:53:57,667] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Committing offsets
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:53:57,667] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} flushing 0 outstanding
> > messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:53:57,682] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Finished commitOffsets
> > successfully in 15 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:54:11,988] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-1} Committing offsets
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:54:11,988] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-1} flushing 0 outstanding
> > messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:54:12,036] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-1} Finished commitOffsets
> > successfully in 48 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:54:12,036] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-2} Committing offsets
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:54:12,036] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-2} flushing 0 outstanding
> > messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:54:12,067] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-2} Finished commitOffsets
> > successfully in 31 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:54:12,067] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-3} Committing offsets
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:54:12,067] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-3} flushing 0 outstanding
> > messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:54:12,101] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-3} Finished commitOffsets
> > successfully in 34 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:54:12,102] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-0} Committing offsets
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:54:12,102] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-0} flushing 0 outstanding
> > messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:54:12,134] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-0} Finished commitOffsets
> > successfully in 32 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:54:19,951] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Committing offsets
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:54:19,951] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} flushing 0 outstanding
> > messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:54:19,955] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Finished commitOffsets
> > successfully in 4 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:54:57,636] INFO
> WorkerSourceTask{id=MirrorSourceConnector-1}
> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:54:57,636] INFO
> WorkerSourceTask{id=MirrorSourceConnector-1}
> > flushing 0 outstanding messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:54:57,637] INFO
> WorkerSourceTask{id=MirrorSourceConnector-2}
> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:54:57,637] INFO
> WorkerSourceTask{id=MirrorSourceConnector-2}
> > flushing 0 outstanding messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:54:57,638] INFO
> WorkerSourceTask{id=MirrorSourceConnector-0}
> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:54:57,639] INFO
> WorkerSourceTask{id=MirrorSourceConnector-0}
> > flushing 0 outstanding messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:54:57,639] INFO
> WorkerSourceTask{id=MirrorSourceConnector-3}
> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:54:57,639] INFO
> WorkerSourceTask{id=MirrorSourceConnector-3}
> > flushing 0 outstanding messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:54:57,682] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Committing offsets
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:54:57,682] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} flushing 0 outstanding
> > messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:54:57,690] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Finished commitOffsets
> > successfully in 8 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:55:12,036] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-1} Committing offsets
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:55:12,036] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-1} flushing 0 outstanding
> > messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:55:12,068] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-1} Finished commitOffsets
> > successfully in 32 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:55:12,068] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-2} Committing offsets
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:55:12,068] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-2} flushing 0 outstanding
> > messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:55:12,099] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-2} Finished commitOffsets
> > successfully in 31 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:55:12,102] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-3} Committing offsets
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:55:12,102] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-3} flushing 0 outstanding
> > messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:55:12,138] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-3} Finished commitOffsets
> > successfully in 36 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:55:12,138] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-0} Committing offsets
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:55:12,138] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-0} flushing 0 outstanding
> > messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:55:12,169] INFO
> > WorkerSourceTask{id=MirrorCheckpointConnector-0} Finished commitOffsets
> > successfully in 31 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:55:19,955] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Committing offsets
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:55:19,955] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} flushing 0 outstanding
> > messages for offset commit
> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:55:19,960] INFO
> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Finished commitOffsets
> > successfully in 5 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > [2020-03-20 10:55:31,729] INFO [Consumer clientId=consumer-14,
> > groupId=null] Subscribed to partition(s): ...
> >
> >
> >
> > and then subscribes to the topics and starts to mirror message:
> > [2020-03-20 10:55:31,729] INFO [Consumer clientId=consumer-14,
> > groupId=null] Subscribed to partition(s): ...
> > [2020-03-20 10:55:31,731] INFO Starting with 303 previously uncommitted
> > partitions. (org.apache.kafka.connect.mirror.MirrorSourceTask)
> > [2020-03-20 10:55:31,732] INFO [Consumer clientId=consumer-14,
> > groupId=null] Seeking to offset 180324042 for partition ...
> >
> > There isn't any logs with "x took too long (y ms)" or "timed out running
> > task x"?
> > Only some "x took y ms", but all of them during the startup and it does
> not
> > seem to be a reason for the 5 minute delay:
> >
> >
> > [2020-03-20 10:49:13,980] INFO Reflections took 1443 ms to scan 92 urls,
> > producing 4486 keys and 18097 values [using 2 cores]
> > (org.reflections.Reflections)
> > [2020-03-20 10:49:14,986] INFO Reflections took 653 ms to scan 92 urls,
> > producing 4486 keys and 18097 values [using 2 cores]
> > (org.reflections.Reflections)
> > [2020-03-20 10:49:16,059] INFO Reflections took 618 ms to scan 92 urls,
> > producing 4486 keys and 18097 values [using 2 cores]
> > (org.reflections.Reflections)
> > [2020-03-20 10:49:19,929] INFO creating internal topics took 13 ms
> > (org.apache.kafka.connect.mirror.Scheduler)
> > [2020-03-20 10:49:20,997] INFO creating internal topics took 10 ms
> > (org.apache.kafka.connect.mirror.Scheduler)
> > [2020-03-20 10:49:57,637] INFO creating internal topics took 21 ms
> > (org.apache.kafka.connect.mirror.Scheduler)
> > [2020-03-20 10:49:57,658] INFO creating upstream offset-syncs topic took
> 29
> > ms (org.apache.kafka.connect.mirror.Scheduler)
> > [2020-03-20 10:49:57,658] INFO creating internal topics took 33 ms
> > (org.apache.kafka.connect.mirror.Scheduler)
> > [2020-03-20 10:49:57,680] INFO loading initial consumer groups took 21 ms
> > (org.apache.kafka.connect.mirror.Scheduler)
> > [2020-03-20 10:49:57,953] INFO loading initial set of topic-partitions
> took
> > 295 ms (org.apache.kafka.connect.mirror.Scheduler)
> > [2020-03-20 10:49:57,964] INFO creating downstream topic-partitions took
> 10
> > ms (org.apache.kafka.connect.mirror.Scheduler)
> > [2020-03-20 10:49:57,980] INFO refreshing known target topics took 15 ms
> > (org.apache.kafka.connect.mirror.Scheduler)
> > [2020-03-20 10:49:57,981] INFO Starting MirrorSourceConnector took 367
> ms.
> > (org.apache.kafka.connect.mirror.MirrorSourceConnector)
> > [2020-03-20 10:49:58,442] INFO syncing topic configs took 461 ms
> > (org.apache.kafka.connect.mirror.Scheduler)
> > [2020-03-20 10:50:07,316] INFO Stopping MirrorSourceConnector took 6051
> ms.
> > (org.apache.kafka.connect.mirror.MirrorSourceConnector)
> > [2020-03-20 10:50:07,329] INFO creating upstream offset-syncs topic took
> 9
> > ms (org.apache.kafka.connect.mirror.Scheduler)
> > [2020-03-20 10:50:07,395] INFO loading initial set of topic-partitions
> took
> > 66 ms (org.apache.kafka.connect.mirror.Scheduler)
> > [2020-03-20 10:50:07,397] INFO creating downstream topic-partitions took
> 2
> > ms (org.apache.kafka.connect.mirror.Scheduler)
> > [2020-03-20 10:50:07,412] INFO refreshing known target topics took 15 ms
> > (org.apache.kafka.connect.mirror.Scheduler)
> > [2020-03-20 10:50:07,412] INFO Starting MirrorSourceConnector took 95 ms.
> > (org.apache.kafka.connect.mirror.MirrorSourceConnector)
> > [2020-03-20 10:50:07,430] INFO creating internal topics took 13 ms
> > (org.apache.kafka.connect.mirror.Scheduler)
> > [2020-03-20 10:50:07,448] INFO creating internal topics took 13 ms
> > (org.apache.kafka.connect.mirror.Scheduler)
> > [2020-03-20 10:50:07,457] INFO loading initial consumer groups took 8 ms
> > (org.apache.kafka.connect.mirror.Scheduler)
> > [2020-03-20 10:50:07,844] INFO syncing topic configs took 432 ms
> > (org.apache.kafka.connect.mirror.Scheduler)
> > [2020-03-20 10:50:09,755] INFO Stopping DistributedHerder-connect-1 took
> > 922 ms. (org.apache.kafka.connect.mirror.MirrorCheckpointTask)
> > [2020-03-20 10:50:10,749] INFO Stopping DistributedHerder-connect-1 took
> > 994 ms. (org.apache.kafka.connect.mirror.MirrorCheckpointTask)
> > [2020-03-20 10:50:10,755] INFO Stopping DistributedHerder-connect-1 took
> 6
> > ms. (org.apache.kafka.connect.mirror.MirrorCheckpointTask)
> > [2020-03-20 10:50:11,749] INFO Stopping DistributedHerder-connect-1 took
> > 994 ms. (org.apache.kafka.connect.mirror.MirrorCheckpointTask)
> > [2020-03-20 10:50:11,859] INFO Stopping
> > task-thread-MirrorCheckpointConnector-3 took 3 ms.
> > (org.apache.kafka.connect.mirror.MirrorCheckpointTask)
> > [2020-03-20 10:50:11,861] INFO Stopping
> > task-thread-MirrorCheckpointConnector-2 took 7 ms.
> > (org.apache.kafka.connect.mirror.MirrorCheckpointTask)
> > [2020-03-20 10:50:11,861] INFO Stopping
> > task-thread-MirrorCheckpointConnector-0 took 5 ms.
> > (org.apache.kafka.connect.mirror.MirrorCheckpointTask)
> > [2020-03-20 10:50:11,862] INFO Stopping
> > task-thread-MirrorCheckpointConnector-1 took 6 ms.
> > (org.apache.kafka.connect.mirror.MirrorCheckpointTask)
> >
> >
> >
> >
> > Peter
> >
> > On Wed, 18 Mar 2020 at 15:12, Ryanne Dolan <ryannedo...@gmail.com>
> wrote:
> >
> > > Peter, can you share any log lines like "x took y ms" or "x took too
> long
> > > (y ms)" or "timed out running task x"?
> > >
> > > Ryanne
> > >
> > > On Tue, Mar 17, 2020 at 10:45 AM Péter Sinóros-Szabó
> > > <peter.sinoros-sz...@transferwise.com.invalid> wrote:
> > >
> > > > Hey,
> > > >
> > > > Running a MM2 cluster to mirror from A->B clusters I noticed that
> when
> > I
> > > > add a new topic to A cluster, MM2 will notice it:
> > > > [2020-03-17 13:14:05,477] INFO Found 2719 topic-partitions on main. 1
> > are
> > > > new. 0 were removed. Previously had 2718.
> > > > (org.apache.kafka.connect.mirror.MirrorSourceConnector)
> > > >
> > > > That's fine. It seems that MM2 connectors just simply restart to
> start
> > up
> > > > with the new configuration.
> > > > My problem is that it takes about 5 minutes for MM2 to start to
> mirror
> > > > messages again.
> > > >
> > > > What I see in the logs are:
> > > > [2020-03-17 13:14:07,107] INFO Kafka startTimeMs: 1584450847106
> > > > (org.apache.kafka.common.utils.AppInfoParser)
> > > > [2020-03-17 13:14:07,204] INFO [Producer clientId=producer-11]
> Cluster
> > > ID:
> > > > wif2mnkZTayzAEOb2VyoLA (org.apache.kafka.clients.Metadata)
> > > >
> > > > It seems that MM2 restarts the connectors in 2 seconds.
> > > > But then I see the usual logs, but according to MM2's metrics, it is
> > not
> > > > mirroring any messages for about 5 minutes.
> > > >
> > > > [2020-03-17 13:14:10,485] INFO
> > > > WorkerSourceTask{id=MirrorCheckpointConnector-3} Committing offsets
> > > > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > > > [2020-03-17 13:14:10,485] INFO
> > > > WorkerSourceTask{id=MirrorCheckpointConnector-3} Committing offsets
> > > > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > > > [2020-03-17 13:14:10,485] INFO
> > > > WorkerSourceTask{id=MirrorCheckpointConnector-3} flushing 0
> outstanding
> > > > messages for offset commit
> > > > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > > > [2020-03-17 13:14:10,485] INFO
> > > > WorkerSourceTask{id=MirrorCheckpointConnector-3} flushing 0
> outstanding
> > > > messages for offset commit
> > > > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > > > [2020-03-17 13:14:10,637] INFO
> > > > WorkerSourceTask{id=MirrorCheckpointConnector-3} Finished
> commitOffsets
> > > > successfully in 152 ms
> > > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > > > [2020-03-17 13:14:10,637] INFO
> > > > WorkerSourceTask{id=MirrorCheckpointConnector-3} Finished
> commitOffsets
> > > > successfully in 152 ms
> > > (org.apache.kafka.connect.runtime.WorkerSourceTask)
> > > >
> > > > So after ~5 minutes, I see that it is subscribing to the topics...
> and
> > I
> > > > also see in the metrics that that is the time when it starts to
> mirror
> > > > messages.
> > > >
> > > > [2020-03-17 13:19:39,850] INFO [Consumer clientId=consumer-39,
> > > > groupId=null] Subscribed to partition(s): ...
> > > > [2020-03-17 13:19:39,851] INFO Starting with 308 previously
> uncommitted
> > > > partitions. (org.apache.kafka.connect.mirror.MirrorSourceTask)
> > > > [2020-03-17 13:19:39,851] INFO [Consumer clientId=consumer-39,
> > > > groupId=null] Seeking to offset 178508243 for partition
> > > > twTasks.austrac-service.executeTask.default-0 (org.apache.kafka
> > > >
> > > >
> > > > Is there any idea how to speed this up?
> > > >
> > > > Thanks,
> > > > Peter
> > > >
> > >
> >
>
