Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

BinlogReader logging EventDataDeserializationException on app startup #50

Open
fatboyslimfast opened this issue Jul 22, 2021 · 1 comment
Open

BinlogReader logging EventDataDeserializationException on app startup #50

fatboyslimfast opened this issue Jul 22, 2021 · 1 comment

Comments

@fatboyslimfast
Copy link

fatboyslimfast commented Jul 22, 2021 •
edited
Loading

We have a Java 11 Spring boot app integrated with Kafka/Debezium.

Versions

debeziumSpringbootStarterVersion=1.0.4.RELEASE
kafkaVersion=2.8.0
debeziumConnectorMysql=1.0.0.Final
mysqlBinlogConnector=0.21.0

On a Mysql (5.7) database database change is made (user dropped/ tables recreated with data) Debezium's binlogreader starts to read the bin logs, but then logs the following Exception

2021-07-22 10:05:08.584  INFO 24570 --- [debyte.com:3306] i.d.r.history.DatabaseHistoryMetrics     : Already applied 10969 database changes
2021-07-22 10:05:10.134 ERROR 24570 --- [debyte.com:3306] i.debezium.connector.mysql.BinlogReader  : Error while deserializing binlog event at offset {ts_sec=1626941231, file=mysql-bin.000532, pos=75496603, server_id=2001, event=876}.
Use the mysqlbinlog tool to view the problematic event: mysqlbinlog --start-position=82610388 --stop-position=82618497 --verbose mysql-bin.000532
2021-07-22 10:05:10.135 ERROR 24570 --- [debyte.com:3306] i.debezium.connector.mysql.BinlogReader  : Error during binlog processing. Last offset stored = {ts_sec=1626941227, file=mysql-bin.000532, pos=71066122, row=272, server_id=2001, event=518}, binlog reader near position = mysql-bin.000532/82610388
2021-07-22 10:05:10.150 ERROR 24570 --- [debyte.com:3306] i.debezium.connector.mysql.BinlogReader  : Failed due to error: Error processing binlog event

org.apache.kafka.connect.errors.ConnectException: com.github.shyiko.mysql.binlog.event.deserialization.EventDataDeserializationException: Failed to deserialize data of EventHeaderV4{timestamp=1626941231000, eventType=EXT_WRITE_ROWS, serverId=2001, headerLength=19, dataLength=8090, nextPosition=82618497, flags=0}
    at io.debezium.connector.mysql.AbstractReader.wrap(AbstractReader.java:230) ~[debezium-connector-mysql-1.0.0.Final.jar:1.0.0.Final]
    at io.debezium.connector.mysql.AbstractReader.failed(AbstractReader.java:207) ~[debezium-connector-mysql-1.0.0.Final.jar:1.0.0.Final]
    at io.debezium.connector.mysql.BinlogReader.handleEvent(BinlogReader.java:536) ~[debezium-connector-mysql-1.0.0.Final.jar:1.0.0.Final]
    at com.github.shyiko.mysql.binlog.BinaryLogClient.notifyEventListeners(BinaryLogClient.java:1158) ~[mysql-binlog-connector-java-0.21.0.jar:0.21.0]
    at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:1005) ~[mysql-binlog-connector-java-0.21.0.jar:0.21.0]
    at com.github.shyiko.mysql.binlog.BinaryLogClient.connectWithTimeout(BinaryLogClient.java:517) ~[mysql-binlog-connector-java-0.21.0.jar:0.21.0]
    at com.github.shyiko.mysql.binlog.BinaryLogClient.access$1100(BinaryLogClient.java:90) ~[mysql-binlog-connector-java-0.21.0.jar:0.21.0]
    at com.github.shyiko.mysql.binlog.BinaryLogClient$7.run(BinaryLogClient.java:881) ~[mysql-binlog-connector-java-0.21.0.jar:0.21.0]
    at java.base/java.lang.Thread.run(Thread.java:829) ~[na:na]
Caused by: java.lang.RuntimeException: com.github.shyiko.mysql.binlog.event.deserialization.EventDataDeserializationException: Failed to deserialize data of EventHeaderV4{timestamp=1626941231000, eventType=EXT_WRITE_ROWS, serverId=2001, headerLength=19, dataLength=8090, nextPosition=82618497, flags=0}
    at io.debezium.connector.mysql.BinlogReader.handleServerIncident(BinlogReader.java:604) ~[debezium-connector-mysql-1.0.0.Final.jar:1.0.0.Final]
    at io.debezium.connector.mysql.BinlogReader.handleEvent(BinlogReader.java:519) ~[debezium-connector-mysql-1.0.0.Final.jar:1.0.0.Final]
    ... 6 common frames omitted
Caused by: com.github.shyiko.mysql.binlog.event.deserialization.EventDataDeserializationException: Failed to deserialize data of EventHeaderV4{timestamp=1626941231000, eventType=EXT_WRITE_ROWS, serverId=2001, headerLength=19, dataLength=8090, nextPosition=82618497, flags=0}
    at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.deserializeEventData(EventDeserializer.java:300) ~[mysql-binlog-connector-java-0.21.0.jar:0.21.0]
    at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.nextEvent(EventDeserializer.java:223) ~[mysql-binlog-connector-java-0.21.0.jar:0.21.0]
    at io.debezium.connector.mysql.BinlogReader$1.nextEvent(BinlogReader.java:239) ~[debezium-connector-mysql-1.0.0.Final.jar:1.0.0.Final]
    at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:984) ~[mysql-binlog-connector-java-0.21.0.jar:0.21.0]
    ... 4 common frames omitted
Caused by: java.io.EOFException: null
    at com.github.shyiko.mysql.binlog.io.ByteArrayInputStream.read(ByteArrayInputStream.java:190) ~[mysql-binlog-connector-java-0.21.0.jar:0.21.0]
    at java.base/java.io.InputStream.read(InputStream.java:271) ~[na:na]
    at java.base/java.io.InputStream.skip(InputStream.java:531) ~[na:na]
    at com.github.shyiko.mysql.binlog.io.ByteArrayInputStream.skipToTheEndOfTheBlock(ByteArrayInputStream.java:216) ~[mysql-binlog-connector-java-0.21.0.jar:0.21.0]
    at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.deserializeEventData(EventDeserializer.java:296) ~[mysql-binlog-connector-java-0.21.0.jar:0.21.0]
    ... 7 common frames omitted

2021-07-22 10:05:10.150  INFO 24570 --- [debyte.com:3306] i.debezium.connector.mysql.BinlogReader  : Error processing binlog event, and propagating to Kafka Connect so it stops this connector. Future binlog events read before connector is shutdown will be ignored.
2021-07-22 10:05:10.152  INFO 24570 --- [debyte.com:3306] i.debezium.connector.mysql.BinlogReader  : Stopped reading binlog after 167936 events, last recorded offset: {ts_sec=1626941227, file=mysql-bin.000532, pos=71066122, row=272, server_id=2001, event=518}
2021-07-22 10:05:37.521  INFO 24570 --- [pool-1-thread-1] i.d.connector.mysql.MySqlConnectorTask   : Stopping MySQL connector task

This also is logged on application restart.

The suggested mysqlbinlog command:

mysqlbinlog --start-position=82610388 --stop-position=82618497 --verbose mysql-bin.000532

Returns

/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#210722  8:06:26 server id 2001  end_log_pos 123 CRC32 0xc7bff6dc   Start: binlog v 4, server v 5.7.19-log created 210722  8:06:26
BINLOG '
Aif5YA/RBwAAdwAAAHsAAAAAAAQANS43LjE5LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
Adz2v8c=
'/*!*/;
# at 82610388
#210722  8:07:11 server id 2001  end_log_pos 82618497 CRC32 0xd2561ccc  Write_rows: table id 43469
WARNING: The range of printed events ends with a row event or a table map event that does not have the STMT_END_F flag set. This might be because the last statement was not fully written to the log, or because you are using a --stop-position or --stop-datetime that refers to an event in the middle of a statement. The event(s) from the partial statement have not been written to output.
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

I have no idea why this is happening or how to code around it. The error is not thrown up to the app and handled internally.

Debugging the inputStream where the error is thrown from

 private EventData deserializeEventData(ByteArrayInputStream inputStream, EventHeader eventHeader,
            EventDataDeserializer eventDataDeserializer) throws EventDataDeserializationException {

       inputStream.skipToTheEndOfTheBlock();

with

new String(inputStream.readAllBytes(), StandardCharsets.UTF_8);

Does indeed throw

Method threw 'java.io.EOFException' exception.

Has anyone else had a similar issue and know what I've got wrong or need to check?
@morozov morozov mentioned this issue Oct 1, 2021
Merged
@ldwnt
Copy link

ldwnt commented Dec 27, 2022

I have seen a similar exception as below. Debezium 1.5.4 & mysql-binlog-connector-java 0.25.1 is used. The exception keeps occuring in few seconds and then seem to disappear, and binlog reading resumes

2022-12-26 19:06:00,687 ERROR [blc-172.19.238.10:3306] io.debezium.connector.mysql.MySqlStreamingChangeEventSource [1046] - Error during binlog processing. Last offset stored = null, binlog reader near position = mysql-bin.000124/262048042
2022-12-26 19:06:00,688 ERROR [blc-172.19.238.10:3306] io.debezium.pipeline.ErrorHandler [31] - Producer failure
io.debezium.DebeziumException: null
	at io.debezium.connector.mysql.MySqlStreamingChangeEventSource.wrap(MySqlStreamingChangeEventSource.java:1146) ~[debezium-connector-mysql-1.5.4.Final.jar:1.5.4.Final]
	at io.debezium.connector.mysql.MySqlStreamingChangeEventSource$ReaderThreadLifecycleListener.onCommunicationFailure(MySqlStreamingChangeEventSource.java:1185) [debezium-connector-mysql-1.5.4.Final.jar:1.5.4.Final]
	at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:973) [mysql-binlog-connector-java-0.25.1.jar:0.25.1]
	at com.github.shyiko.mysql.binlog.BinaryLogClient.connect(BinaryLogClient.java:606) [mysql-binlog-connector-java-0.25.1.jar:0.25.1]
	at com.github.shyiko.mysql.binlog.BinaryLogClient$7.run(BinaryLogClient.java:850) [mysql-binlog-connector-java-0.25.1.jar:0.25.1]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]
Caused by: java.io.EOFException
	at com.github.shyiko.mysql.binlog.io.ByteArrayInputStream.read(ByteArrayInputStream.java:209) ~[mysql-binlog-connector-java-0.25.1.jar:0.25.1]
	at com.github.shyiko.mysql.binlog.io.ByteArrayInputStream.readInteger(ByteArrayInputStream.java:51) ~[mysql-binlog-connector-java-0.25.1.jar:0.25.1]
	at com.github.shyiko.mysql.binlog.event.deserialization.EventHeaderV4Deserializer.deserialize(EventHeaderV4Deserializer.java:35) ~[mysql-binlog-connector-java-0.25.1.jar:0.25.1]
	at com.github.shyiko.mysql.binlog.event.deserialization.EventHeaderV4Deserializer.deserialize(EventHeaderV4Deserializer.java:27) ~[mysql-binlog-connector-java-0.25.1.jar:0.25.1]
	at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.nextEvent(EventDeserializer.java:221) ~[mysql-binlog-connector-java-0.25.1.jar:0.25.1]
	at io.debezium.connector.mysql.MySqlStreamingChangeEventSource$1.nextEvent(MySqlStreamingChangeEventSource.java:233) ~[debezium-connector-mysql-1.5.4.Final.jar:1.5.4.Final]
	at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:945) ~[mysql-binlog-connector-java-0.25.1.jar:0.25.1]
	... 3 more
2022-12-26 19:06:00,694 INFO  [blc-172.19.238.10:3306] io.debezium.connector.mysql.MySqlStreamingChangeEventSource [1159] - Stopped reading binlog after 0 events, no new offset was recorded

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@ldwnt @fatboyslimfast