Investigate mysql binlog reader error

[subkanthi]

debezium-embedded_1  | INFO: Connected to fpif1-txnrepodbl1:3306 at binary.060519/236727937 (sid:976, cid:8830)
debezium-embedded_1  | 1326958 2023-10-19 17:17:12.322 [blc-fpif1-txnrepodbl1:3306] INFO io.debezium.connector.mysql.MySqlStreamingChangeEventSource  - Connected to MySQL binlog at fpif1-txnrepodbl1:3306, starting at MySqlOffsetContext [sourceInfoSchema=Schema{io.debezium.connector.mysql.Source:STRUCT}, sourceInfo=SourceInfo [currentGtid=null, currentBinlogFilename=binary.060519, currentBinlogPosition=236719761, currentRowNumber=27, serverId=50, sourceTime=2023-10-18T19:15:39Z, threadId=44106558, currentQuery=null, tableIds=[txnrepo_prod._trade_gho], databaseName=txnrepo_prod], snapshotCompleted=false, transactionContext=TransactionContext [currentTransactionId=null, perTableEventCount={}, totalEventCount=0], restartGtidSet=null, currentGtidSet=null, restartBinlogFilename=binary.060519, restartBinlogPosition=234093780, restartRowsToSkip=0, restartEventsToSkip=330, currentEventLengthInBytes=8176, inTransaction=true, transactionId=file=binary.060519,pos=234093780, incrementalSnapshotContext =IncrementalSnapshotContext [windowOpened=false, chunkEndPosition=null, dataCollectionsToSnapshot=[], lastEventKeySent=null, maximumKey=null]]
debezium-embedded_1  | 1326958 2023-10-19 17:17:12.322 [blc-fpif1-txnrepodbl1:3306] ERROR io.debezium.connector.mysql.MySqlStreamingChangeEventSource  - Error during binlog processing. Last offset stored = {transaction_id=null, ts_sec=1697656539, file=binary.060519, pos=236727937, server_id=216, event=2}, binlog reader near position = binary.060519/236727937
debezium-embedded_1  | 1326958 2023-10-19 17:17:12.322 [blc-fpif1-txnrepodbl1:3306] ERROR io.debezium.pipeline.ErrorHandler  - Producer failure
debezium-embedded_1  | io.debezium.DebeziumException: Failed to deserialize data of EventHeaderV4{timestamp=1697656539000, eventType=EXT_WRITE_ROWS, serverId=50, headerLength=19, dataLength=8031, nextPosition=236735987, flags=0}
debezium-embedded_1  | 	at io.debezium.connector.mysql.MySqlStreamingChangeEventSource.wrap(MySqlStreamingChangeEventSource.java:1235)
debezium-embedded_1  | 	at io.debezium.connector.mysql.MySqlStreamingChangeEventSource$ReaderThreadLifecycleListener.onEventDeserializationFailure(MySqlStreamingChangeEventSource.java:1288)
debezium-embedded_1  | 	at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:1064)
debezium-embedded_1  | 	at com.github.shyiko.mysql.binlog.BinaryLogClient.connect(BinaryLogClient.java:631)
debezium-embedded_1  | 	at com.github.shyiko.mysql.binlog.BinaryLogClient$7.run(BinaryLogClient.java:932)
debezium-embedded_1  | 	at java.base/java.lang.Thread.run(Thread.java:829)
debezium-embedded_1  | Caused by: com.github.shyiko.mysql.binlog.event.deserialization.EventDataDeserializationException: Failed to deserialize data of EventHeaderV4{timestamp=1697656539000, eventType=EXT_WRITE_ROWS, serverId=50, headerLength=19, dataLength=8031, nextPosition=236735987, flags=0}
debezium-embedded_1  | 	at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.deserializeEventData(EventDeserializer.java:341)
debezium-embedded_1  | 	at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.nextEvent(EventDeserializer.java:244)
debezium-embedded_1  | 	at io.debezium.connector.mysql.MySqlStreamingChangeEventSource$1.nextEvent(MySqlStreamingChangeEventSource.java:232)
debezium-embedded_1  | 	at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:1051)
debezium-embedded_1  | 	... 3 more
debezium-embedded_1  | Caused by: com.github.shyiko.mysql.binlog.event.deserialization.MissingTableMapEventException: No TableMapEventData has been found for table id:7695. 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
debezium-embedded_1  | 	at com.github.shyiko.mysql.binlog.event.deserialization.AbstractRowsEventDataDeserializer.deserializeRow(AbstractRowsEventDataDeserializer.java:109)
debezium-embedded_1  | 	at com.github.shyiko.mysql.binlog.event.deserialization.WriteRowsEventDataDeserializer.deserializeRows(WriteRowsEventDataDeserializer.java:64)
debezium-embedded_1  | 	at com.github.shyiko.mysql.binlog.event.deserialization.WriteRowsEventDataDeserializer.deserialize(WriteRowsEventDataDeserializer.java:56)
debezium-embedded_1  | 	at com.github.shyiko.mysql.binlog.event.deserialization.WriteRowsEventDataDeserializer.deserialize(WriteRowsEventDataDeserializer.java:32)
debezium-embedded_1  | 	at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.deserializeEventData(EventDeserializer.java:335)
debezium-embedded_1  | 	... 6 more

[subkanthi]

Failed to deserialize data of EventHeaderV4

[aadant]

@subkanthi this bug is currently closed and no one is working on it. Maybe we should reopen ?

[subkanthi]

It looks like this change of debezium has caused this error.

-            <version>2.4.0-SNAPSHOT</version>
+            <version>2.4.0.Final</version>

[subkanthi]

@subkanthi this bug is currently closed and no one is working on it. Maybe we should reopen ?

Unfortunately I dont have permission to reopen, have to create a new one.

[subkanthi]

More bugs related to this .

Reproducability condition:

It seems that there are two important conditions to reproduce: 1) a SMT with some latency and 2) a number of large bulk insert queries.  This seems to cause the loss of the connection with MySQL which we see with:

https://issues.redhat.com/browse/DBZ-7026
https://issues.redhat.com/browse/DBZ-5891

[subkanthi]

Updated to latest debezium version 2.5.0.Alpha1 which has the fix.
Fixed : #356

[subkanthi]

Happens in Ghost environment.