Source MySQL: sporadic `java.io.EOFException: Failed to read remaining bytes` errors

[oleksii-nikitchuk]

Source https://discuss.airbyte.io/t/mysql-source-sporadic-java-io-eofexception-failed-to-read-remaining-bytes-errors/2732

Environment

• Airbyte version: 0.40.4
• OS Version / Instance: Linux Ami 2 , AWS EC2
• Deployment: Docker
• Source Connector and version: MySQL 0.6.8 (AWS RDS 8.0.mysql_aurora.3.02.0)
• Destination Connector and version: Redshift 0.3.47 (S3 Staging)
• Step where error happened: Sync job

Current Behavior

Sync sporadically starts to fail with the following error:

2022-09-28 00:12:25 [1;31mERROR[m i.d.p.ErrorHandler(setProducerThrowable):35 - Producer failure
io.debezium.DebeziumException: Failed to deserialize data of EventHeaderV4{timestamp=1664298076000, eventType=TABLE_MAP, serverId=780484762, headerLength=19, dataLength=775, nextPosition=84654564, flags=0}
	at io.debezium.connector.mysql.MySqlStreamingChangeEventSource.wrap(MySqlStreamingChangeEventSource.java:1189) ~[debezium-connector-mysql-1.9.2.Final.jar:1.9.2.Final]
	at io.debezium.connector.mysql.MySqlStreamingChangeEventSource$ReaderThreadLifecycleListener.onCommunicationFailure(MySqlStreamingChangeEventSource.java:1234) [debezium-connector-mysql-1.9.2.Final.jar:1.9.2.Final]
	at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:980) [mysql-binlog-connector-java-0.25.6.jar:0.25.6]
	at com.github.shyiko.mysql.binlog.BinaryLogClient.connect(BinaryLogClient.java:599) [mysql-binlog-connector-java-0.25.6.jar:0.25.6]
	at com.github.shyiko.mysql.binlog.BinaryLogClient$7.run(BinaryLogClient.java:857) [mysql-binlog-connector-java-0.25.6.jar:0.25.6]
	at java.lang.Thread.run(Thread.java:833) [?:?]
Caused by: com.github.shyiko.mysql.binlog.event.deserialization.EventDataDeserializationException: Failed to deserialize data of EventHeaderV4{timestamp=1664298076000, eventType=TABLE_MAP, serverId=780484762, headerLength=19, dataLength=775, nextPosition=84654564, flags=0}
	at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.deserializeEventData(EventDeserializer.java:309) ~[mysql-binlog-connector-java-0.25.6.jar:0.25.6]
	at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.deserializeTableMapEventData(EventDeserializer.java:281) ~[mysql-binlog-connector-java-0.25.6.jar:0.25.6]
	at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.nextEvent(EventDeserializer.java:228) ~[mysql-binlog-connector-java-0.25.6.jar:0.25.6]
	at io.debezium.connector.mysql.MySqlStreamingChangeEventSource$1.nextEvent(MySqlStreamingChangeEventSource.java:230) ~[debezium-connector-mysql-1.9.2.Final.jar:1.9.2.Final]
	at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:952) ~[mysql-binlog-connector-java-0.25.6.jar:0.25.6]
	... 3 more
Caused by: java.io.EOFException: Failed to read remaining 162 of 614 bytes from position 148781693. Block length: 162. Initial block length: 771.
	at com.github.shyiko.mysql.binlog.io.ByteArrayInputStream.fill(ByteArrayInputStream.java:115) ~[mysql-binlog-connector-java-0.25.6.jar:0.25.6]
	at com.github.shyiko.mysql.binlog.io.ByteArrayInputStream.read(ByteArrayInputStream.java:105) ~[mysql-binlog-connector-java-0.25.6.jar:0.25.6]
	at com.github.shyiko.mysql.binlog.event.deserialization.TableMapEventDataDeserializer.deserialize(TableMapEventDataDeserializer.java:48) ~[mysql-binlog-connector-java-0.25.6.jar:0.25.6]
	at com.github.shyiko.mysql.binlog.event.deserialization.TableMapEventDataDeserializer.deserialize(TableMapEventDataDeserializer.java:27) ~[mysql-binlog-connector-java-0.25.6.jar:0.25.6]
	at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.deserializeEventData(EventDeserializer.java:303) ~[mysql-binlog-connector-java-0.25.6.jar:0.25.6]
	at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.deserializeTableMapEventData(EventDeserializer.java:281) ~[mysql-binlog-connector-java-0.25.6.jar:0.25.6]
	at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.nextEvent(EventDeserializer.java:228) ~[mysql-binlog-connector-java-0.25.6.jar:0.25.6]
	at io.debezium.connector.mysql.MySqlStreamingChangeEventSource$1.nextEvent(MySqlStreamingChangeEventSource.java:230) ~[debezium-connector-mysql-1.9.2.Final.jar:1.9.2.Final]
	at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:952) ~[mysql-binlog-connector-java-0.25.6.jar:0.25.6]
	... 3 more

Expected Behavior

No errors during sync

Logs

logs-1316.txt.zip

Steps to Reproduce

The issue is sporadic, cannot provide exact steps to reproduce it. The only way I managed to fix it is to reset data and start fresh sync. But after a while it fails again.

Are you willing to submit a PR?

Nope

[oleksii-nikitchuk]

maybe related to https://github.com/debezium/debezium/pull/3744

[natalyjazzviolin]

Hi, @alexnikitchuk! If you upgrade the MySQL source connector to the latest version, does that fix the problem?

[oleksii-nikitchuk]

hey @natalyjazzviolin just tested with 1.0.3 and after initial sync during next CDC sync run it failed with the same error

[oleksii-nikitchuk]

maybe related to debezium/debezium#3744

seems like https://github.com/airbytehq/airbyte/pull/17459 did not help: I'm still able to reproduce it in v1.0.3

[choji-pro]

I have the same issue. It says something went wrong in the connection, though it goes all the way to the normalization step and completes successfully. It retries 3 times and fails.

[choji-pro]

Hi @natalyjazzviolin. Are there any updates on this task by any chance ?

[danieldiamond]

+1

[shmf]

+1

[fcatanzaro]

+1 Same thing is happening. On mysql connector 1.0.14 & airbyte 0.40.23

Stack Trace: io.debezium.DebeziumException: Failed to deserialize data of EventHeaderV4{timestamp=1670071787000, eventType=EXT_UPDATE_ROWS, serverId=2021, headerLength=19, dataLength=7687, nextPosition=5405739, flags=0}
	at io.debezium.connector.mysql.MySqlStreamingChangeEventSource.wrap(MySqlStreamingChangeEventSource.java:1194)
	at io.debezium.connector.mysql.MySqlStreamingChangeEventSource$ReaderThreadLifecycleListener.onEventDeserializationFailure(MySqlStreamingChangeEventSource.java:1247)
	at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:1064)
	at com.github.shyiko.mysql.binlog.BinaryLogClient.connect(BinaryLogClient.java:631)
	at com.github.shyiko.mysql.binlog.BinaryLogClient$7.run(BinaryLogClient.java:932)
	at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: com.github.shyiko.mysql.binlog.event.deserialization.EventDataDeserializationException: Failed to deserialize data of EventHeaderV4{timestamp=1670071787000, eventType=EXT_UPDATE_ROWS, serverId=2021, headerLength=19, dataLength=7687, nextPosition=5405739, flags=0}
	at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.deserializeEventData(EventDeserializer.java:341)
	at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.nextEvent(EventDeserializer.java:244)
	at io.debezium.connector.mysql.MySqlStreamingChangeEventSource$1.nextEvent(MySqlStreamingChangeEventSource.java:230)
	at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:1051)
	... 3 more
Caused by: com.github.shyiko.mysql.binlog.event.deserialization.MissingTableMapEventException: No TableMapEventData has been found for table id:1873. 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
	at com.github.shyiko.mysql.binlog.event.deserialization.AbstractRowsEventDataDeserializer.deserializeRow(AbstractRowsEventDataDeserializer.java:109)
	at com.github.shyiko.mysql.binlog.event.deserialization.UpdateRowsEventDataDeserializer.deserializeRows(UpdateRowsEventDataDeserializer.java:71)
	at com.github.shyiko.mysql.binlog.event.deserialization.UpdateRowsEventDataDeserializer.deserialize(UpdateRowsEventDataDeserializer.java:58)
	at com.github.shyiko.mysql.binlog.event.deserialization.UpdateRowsEventDataDeserializer.deserialize(UpdateRowsEventDataDeserializer.java:33)
	at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.deserializeEventData(EventDeserializer.java:335)
	... 6 more```

[marcosmarxm]

@grishick can you check this issue? Look it is affecting a lot of users with MySQL. It doesn't look is reproducible because some connectors work and others fail with the issue.

[grishick]

I am not sure what is causing this behavior. I've added this issue to DB/DW Sources team's MySQL backlog for investigation

[rodireich]

@subodh1810 please take a look

[geo909]

+1 Our production pipeline is broken, this is major for us..

• Deployment: Airbyte Cloud
• Source: AWS RDS 5.7.12 Aurora MySQL
• Destination: BigQuery
• Step where error happened: Sync job

[bleonard]

Thank you all for helping to debug this issue. Unfortunately @choji-pro , the screenshot is too pixelated to see. Can you tell use more about your situation?

@geo909 We are currently under the impression this happens where there is a connection issue in a variety of ways, but that suggests the our auto-retry would help. It sounds like maybe that's not the case for you. What are you seeing? Intermittent issues in timing or something more predictable?

[geo909]

Hi @bleonard and apologies for the late reply.

I'm using Airbyte cloud, and we are given 3 attempts per sync. We have had 2 issues like this so far in the last couple of weeks, where all three attempts failed. Then a manual resync worked on the second or third attempt.

Is this what you are referring to?

Btw. I'm talking to a person from support, the team is looking into it.

[tony11375]

Hello, We have the same issue, any update?

[jasperjorna]

Experiencing the same issue. Tried different versions of the MySQL source connector, but no luck.

[vendys-mingi]

I have same issue, anyone tell me another version for no bugs?

[olivanchenko]

Experiencing the same issue with Aribyte 0.50.1 / MySQL connector 2.0.25. All syncs are failing because of this error. Is there a solution to solve this?