Loading...

Details

Type: Bug
Resolution: Done
Priority: Minor
Fix Version/s: 1.6.2.Final, 1.7.0.Beta1
Affects Version/s: 1.6.0.Final
Component/s: debezium-connector-mysql
Labels:
None

Blocked:
False
Ready:
False
Release Note Text:
Undefined
Target Release:

1.7.GA
Git Pull Request:
https://github.com/debezium/debezium/pull/2593

SFDC Cases Counter:
SFDC Cases Links:

Description

I received the following error during snapshotting the commute_report table due to TIME columns of the table, "work_on_time" and "work_off_time". When checking the data from the database attached below, it seems okay.

related code:

https://github.com/debezium/debezium/blob/672f9588531be5c5426cef10ee733878174afada/debezium-connector-mysql/src/main/java/io/debezium/connector/mysql/MysqlBinaryProtocolFieldReader.java#L33

If you want to ask me some specific query results, feel free to ask me.

Thanks!

Error Log

2021-07-19 07:32:02,507 INFO   MySQL|schedule_server|snapshot    Exporting data from table 'schedule.commute_report' (11 of 74 tables)   [io.debezium.relational.RelationalSnapshotChangeEventSource]
2021-07-19 07:32:02,507 INFO   MySQL|schedule_server|snapshot    Exporting data from table 'schedule.commute_report' (11 of 74 tables)   [io.debezium.relational.RelationalSnapshotChangeEventSource]
2021-07-19 07:32:02,507 INFO   MySQL|schedule_server|snapshot    For table 'schedule.commute_report' using select statement: 'SELECT * FROM `schedule`.`commute_report`'   [io.debezium.relational.RelationalSnapshotChangeEventSource]
2021-07-19 07:32:13,101 INFO   MySQL|schedule_server|snapshot  Snapshot - Final stage   [io.debezium.pipeline.source.AbstractSnapshotChangeEventSource]
2021-07-19 07:32:13,101 ERROR  MySQL|schedule_server|snapshot  Producer failure   [io.debezium.pipeline.ErrorHandler]io.debezium.DebeziumException: java.lang.RuntimeException: Invalid length when read MySQL TIME value. BIN_LEN_TIME is 0 
        at io.debezium.pipeline.source.AbstractSnapshotChangeEventSource.execute(AbstractSnapshotChangeEventSource.java:78) 
        at io.debezium.pipeline.ChangeEventSourceCoordinator.lambda$start$0(ChangeEventSourceCoordinator.java:113) 
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) 
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) 
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) 
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) 
        at java.base/java.lang.Thread.run(Thread.java:834)
    Caused by: java.lang.RuntimeException: Invalid length when read MySQL TIME value. BIN_LEN_TIME is 0 
        at io.debezium.connector.mysql.MysqlBinaryProtocolFieldReader.readTimeField(MysqlBinaryProtocolFieldReader.java:38) 
        at io.debezium.connector.mysql.AbstractMysqlFieldReader.readField(AbstractMysqlFieldReader.java:30) 
        at io.debezium.connector.mysql.MySqlConnection.getColumnValue(MySqlConnection.java:571) 
        at io.debezium.jdbc.JdbcConnection.rowToArray(JdbcConnection.java:1470) 
        at io.debezium.relational.RelationalSnapshotChangeEventSource.createDataEventsForTable(RelationalSnapshotChangeEventSource.java:355) 
        at io.debezium.relational.RelationalSnapshotChangeEventSource.createDataEvents(RelationalSnapshotChangeEventSource.java:306) 
        at io.debezium.relational.RelationalSnapshotChangeEventSource.doExecute(RelationalSnapshotChangeEventSource.java:136) 
        at io.debezium.pipeline.source.AbstractSnapshotChangeEventSource.execute(AbstractSnapshotChangeEventSource.java:69) ... 6 more
2021-07-19 07:32:13,188 INFO   ||  The task will send records to topic 'schedule_topic_commute_report' for the first time. Checking whether topic exists   [org.apache.kafka.connect.runtime.WorkerSourceTask]
2021-07-19 07:32:13,190 INFO   ||  Topic 'schedule_topic_commute_report' already exists.   [org.apache.kafka.connect.runtime.WorkerSourceTask]
2021-07-19 07:32:13,206 INFO   ||  WorkerSourceTask{id=schedule-0} Committing offsets   [org.apache.kafka.connect.runtime.WorkerSourceTask]
2021-07-19 07:32:13,206 INFO   ||  WorkerSourceTask{id=schedule-0} flushing 172 outstanding messages for offset commit   [org.apache.kafka.connect.runtime.WorkerSourceTask]
2021-07-19 07:32:13,226 INFO   ||  WorkerSourceTask{id=schedule-0} Finished commitOffsets successfully in 20 ms   [org.apache.kafka.connect.runtime.WorkerSourceTask]
2021-07-19 07:32:13,226 ERROR  ||  WorkerSourceTask{id=schedule-0} Task threw an uncaught and unrecoverable exception. Task is being killed and will not recover until manually restarted   [org.apache.kafka.connect.runtime.WorkerTask]
    org.apache.kafka.connect.errors.ConnectException: An exception occurred in the change event producer. This connector will be stopped. at io.debezium.pipeline.ErrorHandler.setProducerThrowable(ErrorHandler.java:42) 
        at io.debezium.pipeline.ChangeEventSourceCoordinator.lambda$start$0(ChangeEventSourceCoordinator.java:130) 
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) 
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) 
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) 
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) 
        at java.base/java.lang.Thread.run(Thread.java:834)Caused by: io.debezium.DebeziumException: java.lang.RuntimeException: Invalid length when read MySQL TIME value. BIN_LEN_TIME is 0 
        at io.debezium.pipeline.source.AbstractSnapshotChangeEventSource.execute(AbstractSnapshotChangeEventSource.java:78) 
        at io.debezium.pipeline.ChangeEventSourceCoordinator.lambda$start$0(ChangeEventSourceCoordinator.java:113) ... 5 more
    Caused by: java.lang.RuntimeException: Invalid length when read MySQL TIME value. BIN_LEN_TIME is 0 
        at io.debezium.connector.mysql.MysqlBinaryProtocolFieldReader.readTimeField(MysqlBinaryProtocolFieldReader.java:38) 
        at io.debezium.connector.mysql.AbstractMysqlFieldReader.readField(AbstractMysqlFieldReader.java:30) 
        at io.debezium.connector.mysql.MySqlConnection.getColumnValue(MySqlConnection.java:571) 
        at io.debezium.jdbc.JdbcConnection.rowToArray(JdbcConnection.java:1470) 
        at io.debezium.relational.RelationalSnapshotChangeEventSource.createDataEventsForTable(RelationalSnapshotChangeEventSource.java:355) 
        at io.debezium.relational.RelationalSnapshotChangeEventSource.createDataEvents(RelationalSnapshotChangeEventSource.java:306) 
        at io.debezium.relational.RelationalSnapshotChangeEventSource.doExecute(RelationalSnapshotChangeEventSource.java:136) 
        at io.debezium.pipeline.source.AbstractSnapshotChangeEventSource.execute(AbstractSnapshotChangeEventSource.java:69) ... 6 more
2021-07-19 07:32:13,227 INFO   ||  Stopping down connector   [io.debezium.connector.common.BaseSourceTask]
2021-07-19 07:32:13,229 INFO   ||  Connection gracefully closed   [io.debezium.jdbc.JdbcConnection]
2021-07-19 07:32:13,229 INFO   ||  [Producer clientId=schedule_server-dbhistory] Closing the Kafka producer with timeoutMillis = 30000 ms.   [org.apache.kafka.clients.producer.KafkaProducer]
2021-07-19 07:32:13,231 INFO   ||  Metrics scheduler closed   [org.apache.kafka.common.metrics.Metrics]
2021-07-19 07:32:13,231 INFO   ||  Closing reporter org.apache.kafka.common.metrics.JmxReporter   [org.apache.kafka.common.metrics.Metrics]
2021-07-19 07:32:13,231 INFO   ||  Metrics reporters closed   [org.apache.kafka.common.metrics.Metrics]
2021-07-19 07:32:13,232 INFO   ||  App info kafka.producer for schedule_server-dbhistory unregistered   [org.apache.kafka.common.utils.AppInfoParser]
2021-07-19 07:32:13,232 INFO   ||  [Producer clientId=connector-producer-schedule-0] Closing the Kafka producer with timeoutMillis = 30000 ms.   [org.apache.kafka.clients.producer.KafkaProducer]
2021-07-19 07:32:13,233 INFO   ||  Metrics scheduler closed   [org.apache.kafka.common.metrics.Metrics]
2021-07-19 07:32:13,234 INFO   ||  Closing reporter org.apache.kafka.common.metrics.JmxReporter   [org.apache.kafka.common.metrics.Metrics]
2021-07-19 07:32:13,234 INFO   ||  Metrics reporters closed   [org.apache.kafka.common.metrics.Metrics]
2021-07-19 07:32:13,234 INFO   ||  App info kafka.producer for connector-producer-schedule-0 unregistered   [org.apache.kafka.common.utils.AppInfoParser]
2021-07-19 07:32:13,234 INFO   ||  App info kafka.admin.client for connector-adminclient-schedule-0 unregistered   [org.apache.kafka.common.utils.AppInfoParser]
2021-07-19 07:32:13,235 INFO   ||  Metrics scheduler closed   [org.apache.kafka.common.metrics.Metrics]
2021-07-19 07:32:13,236 INFO   ||  Closing reporter org.apache.kafka.common.metrics.JmxReporter   [org.apache.kafka.common.metrics.Metrics]
2021-07-19 07:32:13,236 INFO   ||  Metrics reporters closed   [org.apache.kafka.common.metrics.Metrics

Data Inspection

MySQL [schedule]> select version();
+------------+
| version() |
+------------+
| 5.7.28-log |
+------------+
 
MySQL [schedule]> select count(*) from commute_report;
+----------+
| count(*) |
+----------+
| 2495883 |
+----------+
1 row in set (0.46 sec)
MySQL [schedule]> select count(*) from commute_report where char_length(work_on_time) = 8;
+----------+
| count(*) |
+----------+
| 391787 |
+----------+
1 row in set (0.94 sec)
MySQL [schedule]> select count(*) from commute_report where char_length(work_on_time) is null;
+----------+
| count(*) |
+----------+
| 2104096 |
+----------+
1 row in set (1.02 sec)
MySQL [schedule]> select count(*) from commute_report where char_length(work_off_time) = 8;
+----------+
| count(*) |
+----------+
| 312928 |
+----------+
1 row in set (0.90 sec)
MySQL [schedule]> select count(*) from commute_report where char_length(work_off_time) is null;
+----------+
| count(*) |
+----------+
| 2182988 |
+----------+
1 row in set (0.92 sec)
MySQL [schedule]> select count(*) from commute_report;
+----------+
| count(*) |
+----------+
| 2495974 |
+----------+
1 row in set (0.46 sec)
MySQL [schedule]> select count(*) from commute_report where char_length(work_off_time) < 8;
+----------+
| count(*) |
+----------+
| 0 |
+----------+
1 row in set (1.07 sec)
MySQL [schedule]> select count(*) from commute_report where char_length(work_on_time) < 8;
+----------+
| count(*) |
+----------+
| 0 |
+----------+
MySQL [******]> select distinct(length(work_on_time)) from commute_report;
+------------------------+
| (length(work_on_time)) |
+------------------------+
| 8 |
| NULL |
+------------------------+
MySQL [******]> describe commute_report;
+-------------------+--------------+------+-----+---------+----------------+
| Field | Type | Null | Key | Default | Extra |
+-------------------+--------------+------+-----+---------+----------------+
| seq | bigint(20) | NO | PRI | NULL | auto_increment |
| work_on_time | time | YES | | NULL | |
| work_off_time | time | YES | | NULL | |

MySQL [schedule]> select count(*) from commute_report;
+----------+
| count(*) |
+----------+
|  2495883 |
+----------+
1 row in set (0.46 sec)MySQL [schedule]> select count(*) from commute_report where char_length(work_on_time) = 8;
+----------+
| count(*) |
+----------+
|   391787 |
+----------+
1 row in set (0.94 sec)MySQL [schedule]> select count(*) from commute_report where char_length(work_on_time)  is null;
+----------+
| count(*) |
+----------+
|  2104096 |
+----------+
1 row in set (1.02 sec)MySQL [schedule]> select count(*) from commute_report where char_length(work_off_time) = 8;
+----------+
| count(*) |
+----------+
|   312928 |
+----------+
1 row in set (0.90 sec)MySQL [schedule]> select count(*) from commute_report where char_length(work_off_time)  is null;
+----------+
| count(*) |
+----------+
|  2182988 |
+----------+
1 row in set (0.92 sec)MySQL [schedule]> select count(*) from commute_report;
+----------+
| count(*) |
+----------+
|  2495974 |
+----------+
1 row in set (0.46 sec)MySQL [schedule]> select count(*) from commute_report where char_length(work_off_time) < 8;
+----------+
| count(*) |
+----------+
|        0 |
+----------+
1 row in set (1.07 sec)MySQL [schedule]> select count(*) from commute_report where char_length(work_on_time) < 8;
+----------+
| count(*) |
+----------+
|        0 |
+----------+


MySQL [******]> select distinct(length(work_on_time)) from commute_report;
+------------------------+
| (length(work_on_time)) |
+------------------------+
|                      8 |
|                   NULL |
+------------------------+

MySQL [******]> describe commute_report;
+-------------------+--------------+------+-----+---------+----------------+
| Field             | Type         | Null | Key | Default | Extra          |
+-------------------+--------------+------+-----+---------+----------------+
| seq               | bigint(20)   | NO   | PRI | NULL    | auto_increment |
| work_on_time      | time         | YES  |     | NULL    |                |
| work_off_time     | time         | YES  |     | NULL    |

Sample Data

MySQL [schedule]> select rand() as ord, seq, work_on_time, work_off_time from commute_report order by ord desc limit 100;
+--------------------+---------+--------------+---------------+
| ord                | seq     | work_on_time | work_off_time |
+--------------------+---------+--------------+---------------+
| 0.9999994337558741 |  545886 | NULL         | NULL          |
| 0.9999993667006487 | 1512064 | NULL         | NULL          |
| 0.9999992577359074 | 2172851 | NULL         | NULL          |
| 0.9999973699450468 | 2461434 | NULL         | NULL          |
| 0.9999968688935013 |  201800 | NULL         | NULL          |
| 0.9999967161565988 | 1972245 | NULL         | NULL          |
|  0.999995737336572 | 2136452 | NULL         | NULL          |
| 0.9999952996149616 | 2150280 | NULL         | NULL          |
| 0.9999949056655121 |  269791 | NULL         | NULL          |
| 0.9999947967007707 | 2288736 | NULL         | NULL          |
|  0.999992986209684 | 2282243 | NULL         | NULL          |
| 0.9999929023906522 | 1422257 | 09:00:14     | 17:53:00      |
| 0.9999925941228798 | 1865928 | 08:00:00     | 17:00:28      |
| 0.9999910350888884 | 1940251 | NULL         | NULL          |
| 0.9999909074976956 | 1173527 | NULL         | NULL          |
|  0.999989660456767 | 1425295 | NULL         | NULL          |
| 0.9999891240149635 | 1618891 | NULL         | NULL          |
|  0.999989098869254 |  499540 | NULL         | NULL          |
| 0.9999872110783935 | 2539554 | NULL         | NULL          |
| 0.9999870853498458 |  315846 | NULL         | NULL          |
| 0.9999869009479758 |  520259 | NULL         | NULL          |
| 0.9999867752194281 |   48107 | NULL         | NULL          |
| 0.9999867016449446 | 1076949 | NULL         | NULL          |
|  0.999986582435655 | 1402073 | NULL         | NULL          |
| 0.9999860813841094 | 2313398 | NULL         | NULL          |
| 0.9999857777729498 |   76006 | NULL         | NULL          |
| 0.9999856036156282 |  102674 | NULL         | NULL          |
| 0.9999854611232741 | 1286372 | NULL         | NULL          |
| 0.9999853335320813 |  456569 | NULL         | NULL          |
| 0.9999849144369223 |  667185 | NULL         | NULL          |
| 0.9999848641455032 | 1048404 | NULL         | NULL          |
|  0.999984706751988 | 1755075 | NULL         | NULL          |
| 0.9999842289835068 |   72423 | NULL         | NULL          |
| 0.9999840781092495 |  587257 | NULL         | NULL          |
| 0.9999840781092495 | 1351906 | NULL         | NULL          |
| 0.9999840781092495 | 1684848 | NULL         | NULL          |
| 0.9999830136075458 | 1451653 | 08:00:00     | 17:00:00      |
| 0.9999829614534815 |  990496 | NULL         | NULL          |
| 0.9999828776344497 | 2156267 | NULL         | NULL          |
| 0.9999827370047408 | 1719500 | NULL         | NULL          |
|  0.999982653185709 | 1606494 | NULL         | NULL          |
| 0.9999825675040321 |  847672 | 08:53:56     | 18:01:37      |
| 0.9999825190752581 | 1886804 | NULL         | NULL          |
|  0.999982282519324 |  134005 | NULL         | NULL          |
| 0.9999819975346159 | 1455372 | NULL         | NULL          |
| 0.9999818047508428 | 1258161 | NULL         | NULL          |
| 0.9999816389754244 | 1036274 | 08:48:04     | 18:05:00      |
| 0.9999807421117841 | 2329483 | NULL         | NULL          |
| 0.9999804887920436 |  670199 | NULL         | NULL          |
| 0.9999798098578861 | 2252123 | NULL         | NULL          |
| 0.9999792817979858 |  863066 | NULL         | NULL          |
| 0.9999783113598621 | 1848779 | NULL         | NULL          |
| 0.9999782340600883 | 1135668 | NULL         | NULL          |
| 0.9999781167134438 |  931394 | 08:41:16     | NULL          |
| 0.9999778233468326 | 1047410 | 07:47:56     | 17:30:15      |
| 0.9999770605936433 |  169871 | NULL         | NULL          |
| 0.9999769013374828 | 2427366 | 13:43:41     | NULL          |
|  0.999976440332808 | 2109681 | NULL         | NULL          |
| 0.9999763565137763 | 1275069 | NULL         | NULL          |
| 0.9999762643128413 | 2136226 | NULL         | NULL          |
| 0.9999756962060702 |  739433 | 08:58:58     | 20:43:16      |
| 0.9999756524339092 | 2285353 | NULL         | NULL          |
| 0.9999747322872046 | 1407888 | NULL         | NULL          |
| 0.9999731732532132 | 2042979 | NULL         | NULL          |
| 0.9999728798866019 |  301276 | 12:24:34     | NULL          |
|   0.99997270200399 |  273148 | NULL         | NULL          |
| 0.9999725427478297 |  825897 | NULL         | NULL          |
| 0.9999723350628953 | 1145578 | NULL         | NULL          |
| 0.9999722996726375 | 1409130 | NULL         | NULL          |
|  0.999972140416477 |   32886 | NULL         | NULL          |
| 0.9999721152707675 | 1635839 | NULL         | NULL          |
| 0.9999715806916092 | 2076315 | NULL         | NULL          |
| 0.9999715220182869 |  690143 | NULL         | NULL          |
| 0.9999708998948065 | 1421975 | 08:54:49     | 20:07:10      |
| 0.9999707238748397 | 1548577 | NULL         | NULL          |
| 0.9999704156070672 | 2188698 | NULL         | NULL          |
| 0.9999702982604227 | 1874248 | NULL         | NULL          |
| 0.9999702144413909 |  332017 | NULL         | NULL          |
| 0.9999692337587189 |  959988 | NULL         | NULL          |
| 0.9999691396951388 |  739216 | 08:53:54     | 18:11:54      |
| 0.9999689152463981 |  938565 | NULL         | NULL          |
| 0.9999685948714322 | 1220553 | 07:55:58     | 19:07:48      |
| 0.9999685948714322 |  707103 | NULL         | NULL          |
| 0.9999680602922738 | 2147874 | NULL         | NULL          |
| 0.9999670777469567 |  947681 | NULL         | NULL          |
| 0.9999663066118641 |  391139 | 07:50:17     | 17:32:12      |
| 0.9999656965955772 | 1760107 | NULL         | NULL          |
| 0.9999653762206113 | 1473565 | NULL         | NULL          |
|  0.999965175054935 |    1537 | 09:00:00     | 18:00:00      |
| 0.9999648565426141 | 1413898 | NULL         | NULL          |
| 0.9999648062511951 | 1333371 | NULL         | NULL          |
| 0.9999646889045506 |  368041 | NULL         | NULL          |
| 0.9999637920409103 |  637028 | NULL         | NULL          |
| 0.9999625114723691 | 1977670 | NULL         | NULL          |
| 0.9999617971479537 |  727641 | NULL         | NULL          |
| 0.9999616881832124 |  763863 | NULL         | NULL          |
| 0.9999615121632456 | 1570595 | 09:53:26     | 19:02:14      |
| 0.9999600471928344 |  847317 | NULL         | NULL          |
|  0.999959475360773 | 1945339 | NULL         | NULL          |
| 0.9999588802456473 |  478220 | NULL         | NULL          |
+--------------------+---------+--------------+---------------+

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

Screen Shot 2021-07-20 at 9.59.54 AM.png
220 kB
2021/07/20 1:00 AM

Issue Links

is duplicated by

DBZ-3793 Invalid length when read MySQL DATE value

Closed

relates to

DBZ-4032 Crash processing MariaDB DATETIME fields returns empty blob instead of null (Snapshotting with useCursorFetch option)

Closed

Crash when processing MySQL 5.7.28 TIME fields returns empty blob instead of null

Details

Description

Error Log

Data Inspection

Sample Data

Attachments

Attachments

Issue Links

Activity

People

Dates