search

eventuate-foundation / eventuate-cdc

Other
73 stars 31 forks source link

io.eventuate.local.mysql.binlog.UpdateRowsDeserializer.deserializeRow fails with EventDataDeserializationException No TableMapEventData has been found for table id #89

Open dartartem opened 3 years ago

dartartem commented 3 years ago

Problem:

After this change: https://github.com/eventuate-foundation/eventuate-cdc/commit/cb3bd8315f8acd277edb6684ab782463fadaddbd

mysql binlog client logs lifecycle events/exceptions.

But after start on clean mysql database, logs are filled up by many similar messages:

com.github.shyiko.mysql.binlog.event.deserialization.EventDataDeserializationException: Failed to deserialize data of EventHeaderV4{timestamp=1605800408000, eventType=EXT_UPDATE_ROWS, serverId=1, headerLength=19, dataLength=61, nextPosition=5506, flags=0}
    at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.deserializeEventData(EventDeserializer.java:233) ~[mysql-binlog-connector-java-0.16.1.jar:0.16.1]
    at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.nextEvent(EventDeserializer.java:201) ~[mysql-binlog-connector-java-0.16.1.jar:0.16.1]
    at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:890) [mysql-binlog-connector-java-0.16.1.jar:0.16.1]
    at com.github.shyiko.mysql.binlog.BinaryLogClient.connect(BinaryLogClient.java:559) [mysql-binlog-connector-java-0.16.1.jar:0.16.1]
    at com.github.shyiko.mysql.binlog.BinaryLogClient$7.run(BinaryLogClient.java:793) [mysql-binlog-connector-java-0.16.1.jar:0.16.1]
    at java.lang.Thread.run(Thread.java:748) [na:1.8.0_131]
Caused by: com.github.shyiko.mysql.binlog.event.deserialization.MissingTableMapEventException: No TableMapEventData has been found for table id:108. 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:104) ~[mysql-binlog-connector-java-0.16.1.jar:0.16.1]
    at io.eventuate.local.mysql.binlog.UpdateRowsDeserializer.deserializeRow(UpdateRowsDeserializer.java:23) ~[main/:na]
    at com.github.shyiko.mysql.binlog.event.deserialization.UpdateRowsEventDataDeserializer.deserializeRows(UpdateRowsEventDataDeserializer.java:71) ~[mysql-binlog-connector-java-0.16.1.jar:0.16.1]
    at com.github.shyiko.mysql.binlog.event.deserialization.UpdateRowsEventDataDeserializer.deserialize(UpdateRowsEventDataDeserializer.java:58) ~[mysql-binlog-connector-java-0.16.1.jar:0.16.1]
    at com.github.shyiko.mysql.binlog.event.deserialization.UpdateRowsEventDataDeserializer.deserialize(UpdateRowsEventDataDeserializer.java:33) ~[mysql-binlog-connector-java-0.16.1.jar:0.16.1]
    at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.deserializeEventData(EventDeserializer.java:227) ~[mysql-binlog-connector-java-0.16.1.jar:0.16.1]
    ... 5 common frames omitted

Also this message is appeared once on each cdc restart.

Related issues:

https://github.com/eventuate-foundation/eventuate-cdc/issues/86 https://github.com/eventuate-foundation/eventuate-cdc/issues/84

Related post: https://github.com/eventuate-foundation/eventuate-cdc/issues/86#issuecomment-730495970

Solution: N/A, Investigate

Probably it is worth to add all TABLE_MAP events to Map<Long, TableMapEventData> tableMapEventByTableId in TableMapper.

Impact: Presumably none. But initial logs are filled up by exceptions and new exception per cdc restart.

Also looks like it somehow related to offset processing (needs more time to tell more).

cer commented 3 years ago

Which class is logging this message? Is it the newly added MySqlBinaryLogClientLifecycleListener? Please be more specific on what you mean by start on clean mysql database - is it simply equivalent to docker-compose up -d cdc-service?

dartartem commented 3 years ago

Which class is logging this message? Is it the newly added MySqlBinaryLogClientLifecycleListener?

yes

is it simply equivalent to docker-compose up -d cdc-service?

yes

Chris, I described the problem here: https://github.com/eventuate-foundation/eventuate-cdc/issues/86#issuecomment-730495970

Just moved to separate issue.

cer commented 3 years ago

Please update the description to describe the impact on the 'user'? Can the exception be ignored?

dartartem commented 3 years ago

@cer unfortunately it is not clear for now. I need to found reason. For now it looks like it related to saving offsets.

cer commented 3 years ago

@cer unfortunately it is not clear for now. I need to found reason. For now it looks like it related to saving offsets.

But does the CDC function correctly? That's the most important thing for the user!

cer commented 3 years ago

Why does the exception not terminate binlog processing?

dartartem commented 3 years ago

Because shyko connector just logs an exception (via lifecycle listener) when it cannot parse an event and it continues working. It cannot parse events because Map<Long, TableMapEventData> tableMapEventByTableId does not contain mapping for some tables. Initial exception appears because we do not save mapping for tables in those we are not interested. Mysql writes something in system tables at first start.

dartartem commented 3 years ago

Exception on restart is appeared because starting (instead of ending) event offset was saved.

I added logging of each event (to this place: https://github.com/eventuate-foundation/eventuate-cdc/blob/wip-db-id-gen/eventuate-local-java-cdc-connector-mysql-binlog/src/main/java/io/eventuate/local/mysql/binlog/MySqlBinaryLogClient.java#L203). Also added logging when offset is saved to offset store (to this place: https://github.com/eventuate-foundation/eventuate-cdc/blob/wip-db-id-gen/eventuate-local-java-cdc-connector-db-log-common/src/main/java/io/eventuate/local/db/log/common/DatabaseOffsetKafkaStore.java#L45).

Full log on cdc-monitoring table update (without fix):

Event{header=EventHeaderV4{timestamp=1606119920000, eventType=ANONYMOUS_GTID, serverId=1, headerLength=19, dataLength=46, nextPosition=3376, flags=0}, data=null}

Event{header=EventHeaderV4{timestamp=1606119920000, eventType=QUERY, serverId=1, headerLength=19, dataLength=58, nextPosition=3453, flags=8}, data=null}

Event{header=EventHeaderV4{timestamp=1606119920000, eventType=TABLE_MAP, serverId=1, headerLength=19, dataLength=46, nextPosition=3518, flags=0}, data=TableMapEventData{tableId=108, database='eventuate', table='cdc_monitoring', columnTypes=15, 8, columnMetadata=1000, 0, columnNullability={1}}}

Event{header=EventHeaderV4{timestamp=1606119920000, eventType=EXT_UPDATE_ROWS, serverId=1, headerLength=19, dataLength=61, nextPosition=3598, flags=0}, data=UpdateRowsEventData{tableId=108, includedColumnsBeforeUpdate={0, 1}, includedColumns={0, 1}, rows=[
    {before=[[B@1658c17b, 1606119910602], after=[[B@79d4d8b3, 1606119920602]}
]}}

Event{header=EventHeaderV4{timestamp=1606119920000, eventType=XID, serverId=1, headerLength=19, dataLength=12, nextPosition=3629, flags=0}, data=null}

Saved io.eventuate.common.eventuate.local.BinlogFileOffset@72d0d724[binlogFilename=mysql-bin.000003,offset=3518,rowsToSkip=0]

We can see following events:

ANONYMOUS_GTID (Ignored by cdc) QUERY (Ignored by cdc) TABLE_MAP EXT_UPDATE_ROWS (starting offset: 3518, ending offset: 3598) XID (Ignored by cdc)

Kafka store saves 3518.

Logs after restart:


Connected to 172.17.0.1:3306 at mysql-bin.000003/3518 (sid:1234567890, cid:45)

Event{header=EventHeaderV4{timestamp=0, eventType=ROTATE, serverId=1, headerLength=19, dataLength=28, nextPosition=0, flags=32}, data=RotateEventData{binlogFilename='mysql-bin.000003', binlogPosition=3518}}

Event{header=EventHeaderV4{timestamp=1606119760000, eventType=FORMAT_DESCRIPTION, serverId=1, headerLength=19, dataLength=100, nextPosition=0, flags=0}, data=null}

2020-11-23 11:25:49.189 ERROR 11559 --- [172.17.0.1:3306] .b.MySqlBinaryLogClientLifecycleListener : Reader MySqlReader deserialization failed.
2020-11-23 11:25:49.199 ERROR 11559 --- [172.17.0.1:3306] .b.MySqlBinaryLogClientLifecycleListener : Reader deserialization failed.

com.github.shyiko.mysql.binlog.event.deserialization.EventDataDeserializationException: Failed to deserialize data of EventHeaderV4{timestamp=1606119920000, eventType=EXT_UPDATE_ROWS, serverId=1, headerLength=19, dataLength=61, nextPosition=3598, flags=0}
    at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.deserializeEventData(EventDeserializer.java:233) ~[mysql-binlog-connector-java-0.16.1.jar:0.16.1]
    at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.nextEvent(EventDeserializer.java:201) ~[mysql-binlog-connector-java-0.16.1.jar:0.16.1]
    at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:890) [mysql-binlog-connector-java-0.16.1.jar:0.16.1]
    at com.github.shyiko.mysql.binlog.BinaryLogClient.connect(BinaryLogClient.java:559) [mysql-binlog-connector-java-0.16.1.jar:0.16.1]
    at com.github.shyiko.mysql.binlog.BinaryLogClient$7.run(BinaryLogClient.java:793) [mysql-binlog-connector-java-0.16.1.jar:0.16.1]
    at java.lang.Thread.run(Thread.java:748) [na:1.8.0_131]
Caused by: com.github.shyiko.mysql.binlog.event.deserialization.MissingTableMapEventException: No TableMapEventData has been found for table id:108. 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:104) ~[mysql-binlog-connector-java-0.16.1.jar:0.16.1]
    at io.eventuate.local.mysql.binlog.UpdateRowsDeserializer.deserializeRow(UpdateRowsDeserializer.java:23) ~[main/:na]
    at com.github.shyiko.mysql.binlog.event.deserialization.UpdateRowsEventDataDeserializer.deserializeRows(UpdateRowsEventDataDeserializer.java:71) ~[mysql-binlog-connector-java-0.16.1.jar:0.16.1]
    at com.github.shyiko.mysql.binlog.event.deserialization.UpdateRowsEventDataDeserializer.deserialize(UpdateRowsEventDataDeserializer.java:58) ~[mysql-binlog-connector-java-0.16.1.jar:0.16.1]
    at com.github.shyiko.mysql.binlog.event.deserialization.UpdateRowsEventDataDeserializer.deserialize(UpdateRowsEventDataDeserializer.java:33) ~[mysql-binlog-connector-java-0.16.1.jar:0.16.1]
    at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.deserializeEventData(EventDeserializer.java:227) ~[mysql-binlog-connector-java-0.16.1.jar:0.16.1]
    ... 5 common frames omitted

Event{header=EventHeaderV4{timestamp=1606119920000, eventType=XID, serverId=1, headerLength=19, dataLength=12, nextPosition=3629, flags=0}, data=null}

Event{header=EventHeaderV4{timestamp=1606119943000, eventType=ANONYMOUS_GTID, serverId=1, headerLength=19, dataLength=46, nextPosition=3694, flags=0}, data=null}

Event{header=EventHeaderV4{timestamp=1606119943000, eventType=QUERY, serverId=1, headerLength=19, dataLength=58, nextPosition=3771, flags=8}, data=null}

Event{header=EventHeaderV4{timestamp=1606119943000, eventType=TABLE_MAP, serverId=1, headerLength=19, dataLength=46, nextPosition=3836, flags=0}, data=TableMapEventData{tableId=108, database='eventuate', table='cdc_monitoring', columnTypes=15, 8, columnMetadata=1000, 0, columnNullability={1}}}

Event{header=EventHeaderV4{timestamp=1606119943000, eventType=EXT_UPDATE_ROWS, serverId=1, headerLength=19, dataLength=61, nextPosition=3916, flags=0}, data=UpdateRowsEventData{tableId=108, includedColumnsBeforeUpdate={0, 1}, includedColumns={0, 1}, rows=[
    {before=[[B@94a076c, 1606119920602], after=[[B@4951da6d, 1606119943778]}
]}}

Event{header=EventHeaderV4{timestamp=1606119943000, eventType=XID, serverId=1, headerLength=19, dataLength=12, nextPosition=3947, flags=0}, data=null}

Saved io.eventuate.common.eventuate.local.BinlogFileOffset@400d0f7c[binlogFilename=mysql-bin.000003,offset=3836,rowsToSkip=0]

We can see that mysql client connected at 3518 position as expected.

There some more events that corresponds to starting of connection:

ROTATE - handled, to get binlog file name (not really important in current case) FORMAT_DESCRIPTION (ignored)

After those events we can see deserialization fail of EXT_UPDATE_ROWS because of missing TABLE_MAP and improperly saved offset. The client tries to reread already processed event.

With added fix (save ending offset), we can see that everything fine:

cdc_monitoring update:

Event{header=EventHeaderV4{timestamp=1606120806000, eventType=ANONYMOUS_GTID, serverId=1, headerLength=19, dataLength=46, nextPosition=1150, flags=0}, data=null}
Event{header=EventHeaderV4{timestamp=1606120806000, eventType=QUERY, serverId=1, headerLength=19, dataLength=58, nextPosition=1227, flags=8}, data=null}
Event{header=EventHeaderV4{timestamp=1606120806000, eventType=TABLE_MAP, serverId=1, headerLength=19, dataLength=46, nextPosition=1292, flags=0}, data=TableMapEventData{tableId=108, database='eventuate', table='cdc_monitoring', columnTypes=15, 8, columnMetadata=1000, 0, columnNullability={1}}}
cdc_monitoring - 108
Event{header=EventHeaderV4{timestamp=1606120806000, eventType=EXT_UPDATE_ROWS, serverId=1, headerLength=19, dataLength=61, nextPosition=1372, flags=0}, data=UpdateRowsEventData{tableId=108, includedColumnsBeforeUpdate={0, 1}, includedColumns={0, 1}, rows=[
    {before=[[B@1f4c309a, 1606120796443], after=[[B@39128f99, 1606120806443]}
]}}
Event{header=EventHeaderV4{timestamp=1606120806000, eventType=XID, serverId=1, headerLength=19, dataLength=12, nextPosition=1403, flags=0}, data=null}
Saved io.eventuate.common.eventuate.local.BinlogFileOffset@2fbf542b[binlogFilename=mysql-bin.000003,offset=1372,rowsToSkip=0]

restart:


Connected to 172.17.0.1:3306 at mysql-bin.000003/1372 (sid:1234567890, cid:33)

Event{header=EventHeaderV4{timestamp=0, eventType=ROTATE, serverId=1, headerLength=19, dataLength=28, nextPosition=0, flags=32}, data=RotateEventData{binlogFilename='mysql-bin.000003', binlogPosition=1372}}

Event{header=EventHeaderV4{timestamp=1606120717000, eventType=FORMAT_DESCRIPTION, serverId=1, headerLength=19, dataLength=100, nextPosition=0, flags=0}, data=null}

Event{header=EventHeaderV4{timestamp=1606120806000, eventType=XID, serverId=1, headerLength=19, dataLength=12, nextPosition=1403, flags=0}, data=null}

Event{header=EventHeaderV4{timestamp=1606120840000, eventType=ANONYMOUS_GTID, serverId=1, headerLength=19, dataLength=46, nextPosition=1468, flags=0}, data=null}

Event{header=EventHeaderV4{timestamp=1606120840000, eventType=QUERY, serverId=1, headerLength=19, dataLength=58, nextPosition=1545, flags=8}, data=null}

Event{header=EventHeaderV4{timestamp=1606120840000, eventType=TABLE_MAP, serverId=1, headerLength=19, dataLength=46, nextPosition=1610, flags=0}, data=TableMapEventData{tableId=108, database='eventuate', table='cdc_monitoring', columnTypes=15, 8, columnMetadata=1000, 0, columnNullability={1}}}
cdc_monitoring - 108

Event{header=EventHeaderV4{timestamp=1606120840000, eventType=EXT_UPDATE_ROWS, serverId=1, headerLength=19, dataLength=61, nextPosition=1690, flags=0}, data=UpdateRowsEventData{tableId=108, includedColumnsBeforeUpdate={0, 1}, includedColumns={0, 1}, rows=[
    {before=[[B@3c711426, 1606120806443], after=[[B@47fcfc65, 1606120840594]}
]}}
2020-11-23 11:40:46.039  INFO 21813 --- [172.17.0.1:3306] i.e.l.mysql.binlog.ColumnOrderExtractor  : Table io.eventuate.local.common.SchemaAndTable@310111da[schema=eventuate,tableName=cdc_monitoring] has these columns {reader_id=1, last_time=2}

Event{header=EventHeaderV4{timestamp=1606120840000, eventType=XID, serverId=1, headerLength=19, dataLength=12, nextPosition=1721, flags=0}, data=null}

Saved io.eventuate.common.eventuate.local.BinlogFileOffset@67b059ab[binlogFilename=mysql-bin.000003,offset=1690,rowsToSkip=0]

So, now client started just after EXT_WRITE_ROWS and works fine.

dartartem commented 3 years ago

To solve exceptions on start it is possible to add all TABLE_MAP events to tableMapEventByTableId. In some cases table id can be changed, so there should be check and clean up. There is a case when a table is dropped, so, because this event (drop table) is not handled, id will be present inside the map until restart or until id is reused. I think it is fine.