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
> > >
> >
>
