Couldn't commit processed log positions with the source database due to a concurrent connector shutdown or restart
1,626 views
Skip to first unread message
Hrvoje Djurdjevic
Aug 21, 2020, 8:47:40 AM8/21/20
to debezium
Hi,
I am receiving the mentioned warning continuously from Debezium Connector for SQL Server, that I am running by using connect-standalone. At a certain moment, I have tried to start two concurent connectors that connect to the same database, but that was yesterday, and after that I restarted this connector several times, and the other connector is stopped, so I don't know where is that information persisted, and why, because, at the moment only one connector is running, so this shouldn't be logged. As CDC does not work, this seems like a problem, regardless of the fact that it is logged as only a warning, because no (other) error is logged but such lines:
WARN Couldn't commit processed log positions with the source database due to a concurrent connector shutdown or restart (io.debezium.connector.common.BaseSourceTask:238)
Could this be a source of the problem?
Brad M
Sep 17, 2020, 6:22:23 AM9/17/20
to debezium
Did you manage to get sorted with this problem?
I've noticed that when starting the connector after it has previously crashed with an error, it spends a bunch of time outputing that error while it recovers. Try leaving it for half an hour to do it thing and the warning message may go away
Gunnar Morling
Sep 18, 2020, 4:19:29 AM9/18/20
to debezium
Hi,
Could you share detailed logs, or ideally even a reproducer for this issue? What's the error causing the connector to crash? It should gracefully shut down really.
Thanks,
--Gunnar
Brad M
Oct 6, 2020, 8:07:26 AM10/6/20
to debezium
Hi Gunnar
I got this behavior was a result the connector being shut down previously due to an error from the kafka broker (that I described in https://groups.google.com/g/debezium/c/sIqpGxN0IIs).
It appears that when you start the connector again, the SourceTaskOffsetCommitter is attempting to flush offsets while the database history is still being recovered. This results in the warning message that Hrvoje originally reported. Given that the recovery can take some time, I suspect that he was stopping the connector prior to the recovery finishing.
Here is an example log output. This one was triggered by the connector being down for longer than the binlog retention, and then restarted several times, but its the same symptom:
2020-10-06 11:44:54,372 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=inventory-connector-0} Committing offsets
2020-10-06 11:44:54,373 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=inventory-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:44:54,419 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=database-name-connector-0} Committing offsets
2020-10-06 11:44:54,420 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=database-name-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:44:54,420 - WARN [SourceTaskOffsetCommitter-1:BaseSourceTask@238] - Couldn't commit processed log positions with the source database due to a concurrent connector shutdown or restart
2020-10-06 11:45:54,374 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=inventory-connector-0} Committing offsets
2020-10-06 11:45:54,374 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=inventory-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:45:54,421 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=database-name-connector-0} Committing offsets
2020-10-06 11:45:54,421 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=database-name-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:45:54,421 - WARN [SourceTaskOffsetCommitter-1:BaseSourceTask@238] - Couldn't commit processed log positions with the source database due to a concurrent connector shutdown or restart
2020-10-06 11:46:54,374 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=inventory-connector-0} Committing offsets
2020-10-06 11:46:54,374 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=inventory-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:46:54,422 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=database-name-connector-0} Committing offsets
2020-10-06 11:46:54,422 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=database-name-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:46:54,422 - WARN [SourceTaskOffsetCommitter-1:BaseSourceTask@238] - Couldn't commit processed log positions with the source database due to a concurrent connector shutdown or restart
2020-10-06 11:47:54,376 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=inventory-connector-0} Committing offsets
2020-10-06 11:47:54,376 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=inventory-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:47:54,422 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=database-name-connector-0} Committing offsets
2020-10-06 11:47:54,422 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=database-name-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:47:54,422 - WARN [SourceTaskOffsetCommitter-1:BaseSourceTask@238] - Couldn't commit processed log positions with the source database due to a concurrent connector shutdown or restart
2020-10-06 11:48:54,376 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=inventory-connector-0} Committing offsets
2020-10-06 11:48:54,377 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=inventory-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:48:54,423 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=database-name-connector-0} Committing offsets
2020-10-06 11:48:54,423 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=database-name-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:48:54,423 - WARN [SourceTaskOffsetCommitter-1:BaseSourceTask@238] - Couldn't commit processed log positions with the source database due to a concurrent connector shutdown or restart
2020-10-06 11:49:54,377 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=inventory-connector-0} Committing offsets
2020-10-06 11:49:54,377 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=inventory-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:49:54,423 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=database-name-connector-0} Committing offsets
2020-10-06 11:49:54,423 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=database-name-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:49:54,423 - WARN [SourceTaskOffsetCommitter-1:BaseSourceTask@238] - Couldn't commit processed log positions with the source database due to a concurrent connector shutdown or restart
2020-10-06 11:50:54,378 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=inventory-connector-0} Committing offsets
2020-10-06 11:50:54,378 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=inventory-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:50:54,424 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=database-name-connector-0} Committing offsets
2020-10-06 11:50:54,424 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=database-name-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:50:54,424 - WARN [SourceTaskOffsetCommitter-1:BaseSourceTask@238] - Couldn't commit processed log positions with the source database due to a concurrent connector shutdown or restart
2020-10-06 11:51:54,378 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=inventory-connector-0} Committing offsets
2020-10-06 11:51:54,378 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=inventory-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:51:54,425 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=database-name-connector-0} Committing offsets
2020-10-06 11:51:54,425 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=database-name-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:51:54,426 - WARN [SourceTaskOffsetCommitter-1:BaseSourceTask@238] - Couldn't commit processed log positions with the source database due to a concurrent connector shutdown or restart
2020-10-06 11:52:54,379 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=inventory-connector-0} Committing offsets
2020-10-06 11:52:54,379 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=inventory-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:52:54,427 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=database-name-connector-0} Committing offsets
2020-10-06 11:52:54,428 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=database-name-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:52:54,428 - WARN [SourceTaskOffsetCommitter-1:BaseSourceTask@238] - Couldn't commit processed log positions with the source database due to a concurrent connector shutdown or restart
2020-10-06 11:53:26,859 - INFO [task-thread-database-name-connector-0:ConsumerCoordinator@292] - [Consumer clientId=database-name-connector-dbhistory, groupId=database-name-connector-dbhistory] Revoke previously assigned partitions dbhistory.database-name-0
2020-10-06 11:53:26,859 - INFO [task-thread-database-name-connector-0:AbstractCoordinator@979] - [Consumer clientId=database-name-connector-dbhistory, groupId=database-name-connector-dbhistory] Member database-name-connector-dbhistory-e3023304-ae59-4297-964f-629eead72a0b sending LeaveGroup request to coordinator cdhost.example.com:9093 (id: 2147483646 rack: null) due to the consumer is being closed
2020-10-06 11:53:26,873 - INFO [task-thread-database-name-connector-0:DatabaseHistoryMetrics@119] - Finished database history recovery of 20131238 change(s) in 571343 ms
2020-10-06 11:44:54,373 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=inventory-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:44:54,419 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=database-name-connector-0} Committing offsets
2020-10-06 11:44:54,420 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=database-name-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:44:54,420 - WARN [SourceTaskOffsetCommitter-1:BaseSourceTask@238] - Couldn't commit processed log positions with the source database due to a concurrent connector shutdown or restart
2020-10-06 11:45:54,374 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=inventory-connector-0} Committing offsets
2020-10-06 11:45:54,374 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=inventory-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:45:54,421 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=database-name-connector-0} Committing offsets
2020-10-06 11:45:54,421 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=database-name-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:45:54,421 - WARN [SourceTaskOffsetCommitter-1:BaseSourceTask@238] - Couldn't commit processed log positions with the source database due to a concurrent connector shutdown or restart
2020-10-06 11:46:54,374 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=inventory-connector-0} Committing offsets
2020-10-06 11:46:54,374 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=inventory-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:46:54,422 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=database-name-connector-0} Committing offsets
2020-10-06 11:46:54,422 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=database-name-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:46:54,422 - WARN [SourceTaskOffsetCommitter-1:BaseSourceTask@238] - Couldn't commit processed log positions with the source database due to a concurrent connector shutdown or restart
2020-10-06 11:47:54,376 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=inventory-connector-0} Committing offsets
2020-10-06 11:47:54,376 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=inventory-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:47:54,422 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=database-name-connector-0} Committing offsets
2020-10-06 11:47:54,422 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=database-name-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:47:54,422 - WARN [SourceTaskOffsetCommitter-1:BaseSourceTask@238] - Couldn't commit processed log positions with the source database due to a concurrent connector shutdown or restart
2020-10-06 11:48:54,376 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=inventory-connector-0} Committing offsets
2020-10-06 11:48:54,377 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=inventory-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:48:54,423 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=database-name-connector-0} Committing offsets
2020-10-06 11:48:54,423 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=database-name-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:48:54,423 - WARN [SourceTaskOffsetCommitter-1:BaseSourceTask@238] - Couldn't commit processed log positions with the source database due to a concurrent connector shutdown or restart
2020-10-06 11:49:54,377 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=inventory-connector-0} Committing offsets
2020-10-06 11:49:54,377 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=inventory-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:49:54,423 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=database-name-connector-0} Committing offsets
2020-10-06 11:49:54,423 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=database-name-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:49:54,423 - WARN [SourceTaskOffsetCommitter-1:BaseSourceTask@238] - Couldn't commit processed log positions with the source database due to a concurrent connector shutdown or restart
2020-10-06 11:50:54,378 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=inventory-connector-0} Committing offsets
2020-10-06 11:50:54,378 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=inventory-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:50:54,424 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=database-name-connector-0} Committing offsets
2020-10-06 11:50:54,424 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=database-name-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:50:54,424 - WARN [SourceTaskOffsetCommitter-1:BaseSourceTask@238] - Couldn't commit processed log positions with the source database due to a concurrent connector shutdown or restart
2020-10-06 11:51:54,378 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=inventory-connector-0} Committing offsets
2020-10-06 11:51:54,378 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=inventory-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:51:54,425 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=database-name-connector-0} Committing offsets
2020-10-06 11:51:54,425 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=database-name-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:51:54,426 - WARN [SourceTaskOffsetCommitter-1:BaseSourceTask@238] - Couldn't commit processed log positions with the source database due to a concurrent connector shutdown or restart
2020-10-06 11:52:54,379 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=inventory-connector-0} Committing offsets
2020-10-06 11:52:54,379 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=inventory-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:52:54,427 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@424] - WorkerSourceTask{id=database-name-connector-0} Committing offsets
2020-10-06 11:52:54,428 - INFO [SourceTaskOffsetCommitter-1:WorkerSourceTask@441] - WorkerSourceTask{id=database-name-connector-0} flushing 0 outstanding messages for offset commit
2020-10-06 11:52:54,428 - WARN [SourceTaskOffsetCommitter-1:BaseSourceTask@238] - Couldn't commit processed log positions with the source database due to a concurrent connector shutdown or restart
2020-10-06 11:53:26,859 - INFO [task-thread-database-name-connector-0:ConsumerCoordinator@292] - [Consumer clientId=database-name-connector-dbhistory, groupId=database-name-connector-dbhistory] Revoke previously assigned partitions dbhistory.database-name-0
2020-10-06 11:53:26,859 - INFO [task-thread-database-name-connector-0:AbstractCoordinator@979] - [Consumer clientId=database-name-connector-dbhistory, groupId=database-name-connector-dbhistory] Member database-name-connector-dbhistory-e3023304-ae59-4297-964f-629eead72a0b sending LeaveGroup request to coordinator cdhost.example.com:9093 (id: 2147483646 rack: null) due to the consumer is being closed
2020-10-06 11:53:26,873 - INFO [task-thread-database-name-connector-0:DatabaseHistoryMetrics@119] - Finished database history recovery of 20131238 change(s) in 571343 ms
Gunnar Morling
Oct 7, 2020, 5:38:22 AM10/7/20
to debezium
Wow, your schema history is *huge*. Out of curiosity, what's your use case so that get to 20M DDL changes?
We might be able to optimize this a bit, but ultimately what's really needed is a tool for compacting such large history topics. We have https://issues.redhat.com/browse/DBZ-747 for tracking this; if you'd be interested in contributing, let us know. In the meantime, you also might look into using the "schema_recovery" snapshot mode if you can ensure a time without any concurrent schema changes. This would allow you to start with a fresh schema history topic, just starting with the current table schemas and thus will be much faster to recover after a restart (unless you capture 20M tables actually ;)
--Gunnar
Hrvoje Djurdjevic
Oct 12, 2020, 5:06:13 AM10/12/20
to debezium
Hi,
thanks for the answer, and apologies for not responding in a timely manner to a request for further information.
Yes, the warning disappeared by itself without my intervention, and it was not related to my issue with CDC stream, which I caused by setting database.history.kafka.recovery.poll.interval.ms to unreasonably high value, without proper understanding of its usage. So basically, after I removed that parameter, connector started to work according to expectations, without any delays. I actually found that parameter defined for mysql connector, and copied it to configuration of MS SQL server connector, and it affected its behaviour too. Anyway, with hindsight I would agree this is justly characterized as only a warning, but still, to understand how to avoid it would be good.
Hrvoje
Reply all
Reply to author
Forward
0 new messages