Closed
Description
Connector Name
source-mysql
Connector Version
3.1.7
What step the error happened?
During the sync
Relevant information
There is a huge part in our binlog file for a massive update of 1.7M rows that happened in our DB. To me, it seems that the connector times out and restarts reading the binlog in the middle thus the table map is not available to the connector. In the following log file, I have removed references to the 'destination' as irrelevant.
a0117286_6815_4c3a_8575_98b3b5ac8274_job_7837_attempt_1_source.txt
Relevant log output
2023-11-09 13:10:11 source > 2023-11-09 13:10:11 INFO i.d.c.c.BaseSourceTask(lambda$start$0):138 - snapshot.mode = when_needed
2023-11-09 13:10:11 source > 2023-11-09 13:10:11 INFO i.d.c.c.BaseSourceTask(lambda$start$0):138 - database.include.list = hackthebox
2023-11-09 13:10:11 source > 2023-11-09 13:10:11 INFO i.d.c.CommonConnectorConfig(getSourceInfoStructMaker):1221 - Loading the custom source info struct maker plugin: io.debezium.connector.mysql.MySqlSourceInfoStructMaker
2023-11-09 13:10:11 source > 2023-11-09 13:10:11 INFO i.d.c.CommonConnectorConfig(getTopicNamingStrategy):973 - Loading the custom topic naming strategy plugin: io.debezium.schema.DefaultTopicNamingStrategy
2023-11-09 13:10:11 source > 2023-11-09 13:10:11 INFO i.d.c.c.BaseSourceTask(getPreviousOffsets):376 - Found previous partition offset MySqlPartition [sourcePartition={server=hackthebox}]: {transaction_id=null, file=mysql-binlog.010396, pos=35842144, row=2, event=1072}
2023-11-09 13:10:11 source > 2023-11-09 13:10:11 INFO i.d.c.m.MySqlConnectorTask(start):100 - Closing connection before starting schema recovery
2023-11-09 13:10:11 source > 2023-11-09 13:10:11 INFO i.d.j.JdbcConnection(lambda$doClose$4):947 - Connection gracefully closed
2023-11-09 13:10:13 source > 2023-11-09 13:10:13 INFO i.d.c.m.MySqlConnectorTask(start):114 - Reconnecting after finishing schema recovery
2023-11-09 13:10:13 source > 2023-11-09 13:10:13 INFO i.d.c.m.MySqlConnection(availableBinlogFiles):397 - Get all known binlogs from MySQL
2023-11-09 13:10:13 source > 2023-11-09 13:10:13 INFO i.d.c.m.MySqlConnectorTask(isBinlogAvailable):329 - MySQL has the binlog file 'mysql-binlog.010396' required by the connector
2023-11-09 13:10:13 source > 2023-11-09 13:10:13 INFO i.d.u.Threads(threadFactory):271 - Requested thread factory for connector MySqlConnector, id = hackthebox named = SignalProcessor
2023-11-09 13:10:13 source > 2023-11-09 13:10:13 INFO i.d.u.Threads(threadFactory):271 - Requested thread factory for connector MySqlConnector, id = hackthebox named = change-event-source-coordinator
2023-11-09 13:10:13 source > 2023-11-09 13:10:13 INFO i.d.u.Threads(threadFactory):271 - Requested thread factory for connector MySqlConnector, id = hackthebox named = blocking-snapshot
2023-11-09 13:10:13 source > 2023-11-09 13:10:13 INFO i.d.u.Threads$3(newThread):288 - Creating thread debezium-mysqlconnector-hackthebox-change-event-source-coordinator
2023-11-09 13:10:13 source > 2023-11-09 13:10:13 INFO i.d.p.s.SignalProcessor(start):105 - SignalProcessor started. Scheduling it every 5000ms
2023-11-09 13:10:13 source > 2023-11-09 13:10:13 INFO i.d.u.Threads$3(newThread):288 - Creating thread debezium-mysqlconnector-hackthebox-SignalProcessor
2023-11-09 13:10:13 source > 2023-11-09 13:10:13 INFO i.d.p.ChangeEventSourceCoordinator(lambda$start$0):131 - Metrics registered
2023-11-09 13:10:13 source > 2023-11-09 13:10:13 INFO i.d.p.ChangeEventSourceCoordinator(lambda$start$0):134 - Context created
2023-11-09 13:10:13 source > 2023-11-09 13:10:13 INFO i.d.c.m.MySqlSnapshotChangeEventSource(getSnapshottingTask):101 - A previous offset indicating a completed snapshot has been found. Neither schema nor data will be snapshotted.
2023-11-09 13:10:13 source > 2023-11-09 13:10:13 INFO i.d.p.ChangeEventSourceCoordinator(doSnapshot):254 - Snapshot ended with SnapshotResult [status=SKIPPED, offset=MySqlOffsetContext [sourceInfoSchema=Schema{io.debezium.connector.mysql.Source:STRUCT}, sourceInfo=SourceInfo [currentGtid=null, currentBinlogFilename=mysql-binlog.010396, currentBinlogPosition=35842144, currentRowNumber=0, serverId=0, sourceTime=null, threadId=-1, currentQuery=null, tableIds=[], databaseName=null], snapshotCompleted=false, transactionContext=TransactionContext [currentTransactionId=null, perTableEventCount={}, totalEventCount=0], restartGtidSet=null, currentGtidSet=null, restartBinlogFilename=mysql-binlog.010396, restartBinlogPosition=35842144, restartRowsToSkip=2, restartEventsToSkip=1072, currentEventLengthInBytes=0, inTransaction=false, transactionId=null, incrementalSnapshotContext =IncrementalSnapshotContext [windowOpened=false, chunkEndPosition=null, dataCollectionsToSnapshot=[], lastEventKeySent=null, maximumKey=null]]]
2023-11-09 13:10:13 source > 2023-11-09 13:10:13 INFO i.d.u.Threads(threadFactory):271 - Requested thread factory for connector MySqlConnector, id = hackthebox named = binlog-client
2023-11-09 13:10:13 source > 2023-11-09 13:10:13 INFO i.d.c.m.MySqlStreamingChangeEventSource(getBinlogSslSocketFactory):1070 - Enable ssl PREFERRED mode for connector hackthebox
2023-11-09 13:10:13 source > 2023-11-09 13:10:13 INFO i.d.p.ChangeEventSourceCoordinator(streamEvents):271 - Starting streaming
2023-11-09 13:10:13 source > 2023-11-09 13:10:13 INFO i.d.c.m.MySqlStreamingChangeEventSource(execute):984 - Skip 1072 events on streaming start
2023-11-09 13:10:13 source > 2023-11-09 13:10:13 INFO i.d.c.m.MySqlStreamingChangeEventSource(execute):988 - Skip 2 rows on streaming start
2023-11-09 13:10:13 source > 2023-11-09 13:10:13 INFO i.d.u.Threads$3(newThread):288 - Creating thread debezium-mysqlconnector-hackthebox-binlog-client
2023-11-09 13:10:13 source > 2023-11-09 13:10:13 INFO i.d.u.Threads$3(newThread):288 - Creating thread debezium-mysqlconnector-hackthebox-binlog-client
2023-11-09 13:10:13 source > Nov 09, 2023 1:10:13 PM com.github.shyiko.mysql.binlog.BinaryLogClient tryUpgradeToSSL
2023-11-09 13:10:13 source > INFO: SSL enabled
2023-11-09 13:10:13 source > Nov 09, 2023 1:10:13 PM com.github.shyiko.mysql.binlog.BinaryLogClient connect
2023-11-09 13:10:13 source > INFO: Connected to 46.101.4.87:3306 at mysql-binlog.010396/35842144 (sid:5890, cid:41919)
2023-11-09 13:10:13 source > 2023-11-09 13:10:13 INFO i.d.c.m.MySqlStreamingChangeEventSource$ReaderThreadLifecycleListener(onConnect):1285 - Connected to MySQL binlog at 46.101.4.87:3306, starting at MySqlOffsetContext [sourceInfoSchema=Schema{io.debezium.connector.mysql.Source:STRUCT}, sourceInfo=SourceInfo [currentGtid=null, currentBinlogFilename=mysql-binlog.010396, currentBinlogPosition=35842144, currentRowNumber=0, serverId=0, sourceTime=null, threadId=-1, currentQuery=null, tableIds=[], databaseName=null], snapshotCompleted=false, transactionContext=TransactionContext [currentTransactionId=null, perTableEventCount={}, totalEventCount=0], restartGtidSet=null, currentGtidSet=null, restartBinlogFilename=mysql-binlog.010396, restartBinlogPosition=35842144, restartRowsToSkip=2, restartEventsToSkip=1072, currentEventLengthInBytes=0, inTransaction=false, transactionId=null, incrementalSnapshotContext =IncrementalSnapshotContext [windowOpened=false, chunkEndPosition=null, dataCollectionsToSnapshot=[], lastEventKeySent=null, maximumKey=null]]
2023-11-09 13:10:13 source > 2023-11-09 13:10:13 INFO i.d.u.Threads$3(newThread):288 - Creating thread debezium-mysqlconnector-hackthebox-binlog-client
2023-11-09 13:10:13 source > 2023-11-09 13:10:13 INFO i.d.c.m.MySqlStreamingChangeEventSource(execute):1005 - Waiting for keepalive thread to start
2023-11-09 13:10:13 source > 2023-11-09 13:10:13 INFO i.d.c.m.MySqlStreamingChangeEventSource(execute):1012 - Keepalive thread is running
2023-11-09 13:14:31 source > Nov 09, 2023 1:12:13 PM com.github.shyiko.mysql.binlog.BinaryLogClient$5 run
2023-11-09 13:14:31 source > INFO: Keepalive: Trying to restore lost connection to 46.101.4.87:3306
2023-11-09 13:14:31 source > 2023-11-09 13:14:31 INFO i.d.c.c.BaseSourceTask(logStatistics):215 - 15756 records sent during previous 00:04:20.004, last recorded offset of {server=hackthebox} partition is {transaction_id=null, ts_sec=1699423236, file=mysql-binlog.010396, pos=49547105, row=3, server_id=1}
2023-11-09 13:14:31 source > 2023-11-09 13:14:31 INFO i.d.u.Threads$3(newThread):288 - Creating thread debezium-mysqlconnector-hackthebox-binlog-client
2023-11-09 13:14:31 source > 2023-11-09 13:14:31 INFO i.d.c.m.MySqlStreamingChangeEventSource$ReaderThreadLifecycleListener(lambda$onDisconnect$0):1270 - Stopped reading binlog after 0 events, last recorded offset: {transaction_id=null, ts_sec=1699423236, file=mysql-binlog.010396, pos=55001289, server_id=1, event=1}
2023-11-09 13:14:31 source > Nov 09, 2023 1:14:31 PM com.github.shyiko.mysql.binlog.BinaryLogClient tryUpgradeToSSL
2023-11-09 13:14:31 source > INFO: SSL enabled
2023-11-09 13:14:31 source > Nov 09, 2023 1:14:31 PM com.github.shyiko.mysql.binlog.BinaryLogClient connect
2023-11-09 13:14:31 source > INFO: Connected to 46.101.4.87:3306 at mysql-binlog.010396/55001289 (sid:5890, cid:41937)
2023-11-09 13:14:31 source > 2023-11-09 13:14:31 INFO i.d.c.m.MySqlStreamingChangeEventSource$ReaderThreadLifecycleListener(onConnect):1285 - Connected to MySQL binlog at 46.101.4.87:3306, starting at MySqlOffsetContext [sourceInfoSchema=Schema{io.debezium.connector.mysql.Source:STRUCT}, sourceInfo=SourceInfo [currentGtid=null, currentBinlogFilename=mysql-binlog.010396, currentBinlogPosition=54993937, currentRowNumber=8, serverId=1, sourceTime=2023-11-08T06:00:36Z, threadId=-1, currentQuery=null, tableIds=[hackthebox.users], databaseName=null], snapshotCompleted=false, transactionContext=TransactionContext [currentTransactionId=null, perTableEventCount={}, totalEventCount=0], restartGtidSet=null, currentGtidSet=null, restartBinlogFilename=mysql-binlog.010396, restartBinlogPosition=55001289, restartRowsToSkip=0, restartEventsToSkip=1, currentEventLengthInBytes=7352, inTransaction=false, transactionId=null, incrementalSnapshotContext =IncrementalSnapshotContext [windowOpened=false, chunkEndPosition=null, dataCollectionsToSnapshot=[], lastEventKeySent=null, maximumKey=null]]
2023-11-09 13:14:31 source > 2023-11-09 13:14:31 ERROR i.d.c.m.MySqlStreamingChangeEventSource(logStreamingSourceState):1161 - Error during binlog processing. Last offset stored = {transaction_id=null, ts_sec=1699423236, file=mysql-binlog.010396, pos=0, server_id=2, event=1}, binlog reader near position = mysql-binlog.010396/55001289
2023-11-09 13:14:31 source > 2023-11-09 13:14:31 ERROR i.d.p.ErrorHandler(setProducerThrowable):52 - Producer failure
2023-11-09 13:14:31 source > io.debezium.DebeziumException: Failed to deserialize data of EventHeaderV4{timestamp=1699423236000, eventType=UPDATE_ROWS, serverId=1, headerLength=19, dataLength=8009, nextPosition=55009317, flags=0}
2023-11-09 13:14:31 source > at io.debezium.connector.mysql.MySqlStreamingChangeEventSource.wrap(MySqlStreamingChangeEventSource.java:1254) ~[debezium-connector-mysql-2.4.0.Final.jar:2.4.0.Final]
2023-11-09 13:14:31 source > at io.debezium.connector.mysql.MySqlStreamingChangeEventSource$ReaderThreadLifecycleListener.onEventDeserializationFailure(MySqlStreamingChangeEventSource.java:1307) [debezium-connector-mysql-2.4.0.Final.jar:2.4.0.Final]
2023-11-09 13:14:31 source > at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:1064) [mysql-binlog-connector-java-0.28.1.jar:0.28.1]
2023-11-09 13:14:31 source > at com.github.shyiko.mysql.binlog.BinaryLogClient.connect(BinaryLogClient.java:631) [mysql-binlog-connector-java-0.28.1.jar:0.28.1]
2023-11-09 13:14:31 source > at com.github.shyiko.mysql.binlog.BinaryLogClient$7.run(BinaryLogClient.java:932) [mysql-binlog-connector-java-0.28.1.jar:0.28.1]
2023-11-09 13:14:31 source > at java.base/java.lang.Thread.run(Thread.java:833) [?:?]
2023-11-09 13:14:31 source > Caused by: com.github.shyiko.mysql.binlog.event.deserialization.EventDataDeserializationException: Failed to deserialize data of EventHeaderV4{timestamp=1699423236000, eventType=UPDATE_ROWS, serverId=1, headerLength=19, dataLength=8009, nextPosition=55009317, flags=0}
2023-11-09 13:14:31 source > at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.deserializeEventData(EventDeserializer.java:343) ~[mysql-binlog-connector-java-0.28.1.jar:0.28.1]
2023-11-09 13:14:31 source > at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.nextEvent(EventDeserializer.java:246) ~[mysql-binlog-connector-java-0.28.1.jar:0.28.1]
2023-11-09 13:14:31 source > at io.debezium.connector.mysql.MySqlStreamingChangeEventSource$1.nextEvent(MySqlStreamingChangeEventSource.java:233) ~[debezium-connector-mysql-2.4.0.Final.jar:2.4.0.Final]
2023-11-09 13:14:31 source > at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:1051) ~[mysql-binlog-connector-java-0.28.1.jar:0.28.1]
2023-11-09 13:14:31 source > ... 3 more
2023-11-09 13:14:31 source > Caused by: com.github.shyiko.mysql.binlog.event.deserialization.MissingTableMapEventException: No TableMapEventData has been found for table id:26. Usually that means that you have started reading binary log 'within the logical event group' (e.g. from WRITE_ROWS and not proceeding TABLE_MAP
2023-11-09 13:14:31 source > at com.github.shyiko.mysql.binlog.event.deserialization.AbstractRowsEventDataDeserializer.deserializeRow(AbstractRowsEventDataDeserializer.java:109) ~[mysql-binlog-connector-java-0.28.1.jar:0.28.1]
2023-11-09 13:14:31 source > at com.github.shyiko.mysql.binlog.event.deserialization.UpdateRowsEventDataDeserializer.deserializeRows(UpdateRowsEventDataDeserializer.java:71) ~[mysql-binlog-connector-java-0.28.1.jar:0.28.1]
2023-11-09 13:14:31 source > at com.github.shyiko.mysql.binlog.event.deserialization.UpdateRowsEventDataDeserializer.deserialize(UpdateRowsEventDataDeserializer.java:58) ~[mysql-binlog-connector-java-0.28.1.jar:0.28.1]
2023-11-09 13:14:31 source > at com.github.shyiko.mysql.binlog.event.deserialization.UpdateRowsEventDataDeserializer.deserialize(UpdateRowsEventDataDeserializer.java:33) ~[mysql-binlog-connector-java-0.28.1.jar:0.28.1]
2023-11-09 13:14:31 source > at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.deserializeEventData(EventDeserializer.java:337) ~[mysql-binlog-connector-java-0.28.1.jar:0.28.1]
2023-11-09 13:14:31 source > at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.nextEvent(EventDeserializer.java:246) ~[mysql-binlog-connector-java-0.28.1.jar:0.28.1]
2023-11-09 13:14:31 source > at io.debezium.connector.mysql.MySqlStreamingChangeEventSource$1.nextEvent(MySqlStreamingChangeEventSource.java:233) ~[debezium-connector-mysql-2.4.0.Final.jar:2.4.0.Final]
2023-11-09 13:14:31 source > at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:1051) ~[mysql-binlog-connector-java-0.28.1.jar:0.28.1]
2023-11-09 13:14:31 source > ... 3 more
2023-11-09 13:14:31 source > 2023-11-09 13:14:31 ERROR i.d.p.ErrorHandler(hasMoreRetries):129 - The maximum number of 0 retries has been attempted
2023-11-09 13:14:31 source > 2023-11-09 13:14:31 ERROR i.d.c.m.MySqlStreamingChangeEventSource(logStreamingSourceState):1161 - Error during binlog processing. Last offset stored = {transaction_id=null, ts_sec=1699423236, file=mysql-binlog.010396, pos=0, server_id=2, event=1}, binlog reader near position = mysql-binlog.010396/55001289
2023-11-09 13:14:31 source > 2023-11-09 13:14:31 ERROR i.d.p.ErrorHandler(setProducerThrowable):52 - Producer failure
2023-11-09 13:14:31 source > io.debezium.DebeziumException: Failed to deserialize data of EventHeaderV4{timestamp=1699423236000, eventType=UPDATE_ROWS, serverId=1, headerLength=19, dataLength=7463, nextPosition=55016799, flags=0}
2023-11-09 13:14:31 source > at io.debezium.connector.mysql.MySqlStreamingChangeEventSource.wrap(MySqlStreamingChangeEventSource.java:1254) ~[debezium-connector-mysql-2.4.0.Final.jar:2.4.0.Final]
2023-11-09 13:14:31 source > at io.debezium.connector.mysql.MySqlStreamingChangeEventSource$ReaderThreadLifecycleListener.onEventDeserializationFailure(MySqlStreamingChangeEventSource.java:1307) [debezium-connector-mysql-2.4.0.Final.jar:2.4.0.Final]
2023-11-09 13:14:31 source > at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:1064) [mysql-binlog-connector-java-0.28.1.jar:0.28.1]
2023-11-09 13:14:31 source > at com.github.shyiko.mysql.binlog.BinaryLogClient.connect(BinaryLogClient.java:631) [mysql-binlog-connector-java-0.28.1.jar:0.28.1]
2023-11-09 13:14:31 source > at com.github.shyiko.mysql.binlog.BinaryLogClient$7.run(BinaryLogClient.java:932) [mysql-binlog-connector-java-0.28.1.jar:0.28.1]
2023-11-09 13:14:31 source > at java.base/java.lang.Thread.run(Thread.java:833) [?:?]
2023-11-09 13:14:31 source > Caused by: com.github.shyiko.mysql.binlog.event.deserialization.EventDataDeserializationException: Failed to deserialize data of EventHeaderV4{timestamp=1699423236000, eventType=UPDATE_ROWS, serverId=1, headerLength=19, dataLength=7463, nextPosition=55016799, flags=0}
2023-11-09 13:14:31 source > at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.deserializeEventData(EventDeserializer.java:343) ~[mysql-binlog-connector-java-0.28.1.jar:0.28.1]
2023-11-09 13:14:31 source > at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.nextEvent(EventDeserializer.java:246) ~[mysql-binlog-connector-java-0.28.1.jar:0.28.1]
2023-11-09 13:14:31 source > at io.debezium.connector.mysql.MySqlStreamingChangeEventSource$1.nextEvent(MySqlStreamingChangeEventSource.java:233) ~[debezium-connector-mysql-2.4.0.Final.jar:2.4.0.Final]
2023-11-09 13:14:31 source > at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:1051) ~[mysql-binlog-connector-java-0.28.1.jar:0.28.1]
2023-11-09 13:14:31 source > ... 3 more
2023-11-09 13:14:31 source > Caused by: com.github.shyiko.mysql.binlog.event.deserialization.MissingTableMapEventException: No TableMapEventData has been found for table id:26. Usually that means that you have started reading binary log 'within the logical event group' (e.g. from WRITE_ROWS and not proceeding TABLE_MAP
2023-11-09 13:14:31 source > at com.github.shyiko.mysql.binlog.event.deserialization.AbstractRowsEventDataDeserializer.deserializeRow(AbstractRowsEventDataDeserializer.java:109) ~[mysql-binlog-connector-java-0.28.1.jar:0.28.1]
2023-11-09 13:14:31 source > at com.github.shyiko.mysql.binlog.event.deserialization.UpdateRowsEventDataDeserializer.deserializeRows(UpdateRowsEventDataDeserializer.java:71) ~[mysql-binlog-connector-java-0.28.1.jar:0.28.1]
2023-11-09 13:14:31 source > at com.github.shyiko.mysql.binlog.event.deserialization.UpdateRowsEventDataDeserializer.deserialize(UpdateRowsEventDataDeserializer.java:58) ~[mysql-binlog-connector-java-0.28.1.jar:0.28.1]
2023-11-09 13:14:31 source > at com.github.shyiko.mysql.binlog.event.deserialization.UpdateRowsEventDataDeserializer.deserialize(UpdateRowsEventDataDeserializer.java:33) ~[mysql-binlog-connector-java-0.28.1.jar:0.28.1]
2023-11-09 13:14:31 source > at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.deserializeEventData(EventDeserializer.java:337) ~[mysql-binlog-connector-java-0.28.1.jar:0.28.1]
2023-11-09 13:14:31 source > at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.nextEvent(EventDeserializer.java:246) ~[mysql-binlog-connector-java-0.28.1.jar:0.28.1]
2023-11-09 13:14:31 source > at io.debezium.connector.mysql.MySqlStreamingChangeEventSource$1.nextEvent(MySqlStreamingChangeEventSource.java:233) ~[debezium-connector-mysql-2.4.0.Final.jar:2.4.0.Final]
2023-11-09 13:14:31 source > at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:1051) ~[mysql-binlog-connector-java-0.28.1.jar:0.28.1]
2023-11-09 13:14:31 source > ... 3 moreContribute
- Yes, I want to contribute