寒玉 Blog

Debezium趟坑记录

Debezium趟坑记录

创建表导致connector报错

这几天发现Debezium上注册的mysql connector 在报一个错误,错误信息如下:

org.apache.kafka.connect.errors.ConnectException: Maximum width must be from 1 to 9 inclusive but was 0
    at io.debezium.connector.mysql.AbstractReader.wrap(AbstractReader.java:230)
    at io.debezium.connector.mysql.AbstractReader.failed(AbstractReader.java:208)
    at io.debezium.connector.mysql.BinlogReader.handleEvent(BinlogReader.java:508)
    at com.github.shyiko.mysql.binlog.BinaryLogClient.notifyEventListeners(BinaryLogClient.java:1095)
    at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:943)
    at com.github.shyiko.mysql.binlog.BinaryLogClient.connect(BinaryLogClient.java:580)
    at com.github.shyiko.mysql.binlog.BinaryLogClient$7.run(BinaryLogClient.java:825)
    at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.IllegalArgumentException: Maximum width must be from 1 to 9 inclusive but was 0
    at java.time.format.DateTimeFormatterBuilder$FractionPrinterParser.<init>(DateTimeFormatterBuilder.java:2922)
    at java.time.format.DateTimeFormatterBuilder.appendFraction(DateTimeFormatterBuilder.java:687)
    at io.debezium.connector.mysql.MySqlDefaultValuePreConverter.timestampFormat(MySqlDefaultValuePreConverter.java:239)
    at io.debezium.connector.mysql.MySqlDefaultValuePreConverter.convertToLocalDateTime(MySqlDefaultValuePreConverter.java:129)
    at io.debezium.connector.mysql.MySqlDefaultValuePreConverter.convert(MySqlDefaultValuePreConverter.java:68)
    at io.debezium.connector.mysql.antlr.listener.ColumnDefinitionParserListener.convertDefaultValueToSchemaType(ColumnDefinitionParserListener.java:303)
    at io.debezium.connector.mysql.antlr.listener.ColumnDefinitionParserListener.enterDefaultValue(ColumnDefinitionParserListener.java:142)
    at io.debezium.ddl.parser.mysql.generated.MySqlParser$DefaultValueContext.enterRule(MySqlParser.java:46698)
    at io.debezium.antlr.ProxyParseTreeListenerUtil.delegateEnterRule(ProxyParseTreeListenerUtil.java:46)
    at io.debezium.connector.mysql.antlr.listener.MySqlAntlrDdlParserListener.enterEveryRule(MySqlAntlrDdlParserListener.java:89)
    at org.antlr.v4.runtime.tree.ParseTreeWalker.enterRule(ParseTreeWalker.java:41)
    at org.antlr.v4.runtime.tree.ParseTreeWalker.walk(ParseTreeWalker.java:25)
    at org.antlr.v4.runtime.tree.ParseTreeWalker.walk(ParseTreeWalker.java:28)
    at org.antlr.v4.runtime.tree.ParseTreeWalker.walk(ParseTreeWalker.java:28)
    at org.antlr.v4.runtime.tree.ParseTreeWalker.walk(ParseTreeWalker.java:28)
    at org.antlr.v4.runtime.tree.ParseTreeWalker.walk(ParseTreeWalker.java:28)
    at org.antlr.v4.runtime.tree.ParseTreeWalker.walk(ParseTreeWalker.java:28)
    at org.antlr.v4.runtime.tree.ParseTreeWalker.walk(ParseTreeWalker.java:28)
    at org.antlr.v4.runtime.tree.ParseTreeWalker.walk(ParseTreeWalker.java:28)
    at org.antlr.v4.runtime.tree.ParseTreeWalker.walk(ParseTreeWalker.java:28)
    at org.antlr.v4.runtime.tree.ParseTreeWalker.walk(ParseTreeWalker.java:28)
    at io.debezium.antlr.AntlrDdlParser.parse(AntlrDdlParser.java:85)
    at io.debezium.connector.mysql.MySqlSchema.applyDdl(MySqlSchema.java:307)
    at io.debezium.connector.mysql.BinlogReader.handleQueryEvent(BinlogReader.java:694)
    at io.debezium.connector.mysql.BinlogReader.handleEvent(BinlogReader.java:492)

很明显是一个日期格式解析的错误,但是会是什么日期呢,根据错误日志,往回翻了下日志,找到了相联系的上次条出错日志

[2019-07-19 09:38:05,247] ERROR Error during binlog processing. Last offset stored = {ts_sec=1562746455, file=mariadb-bin.000018, pos=58777691, row=1, server_id=1, event=6}, binlog reader near position = mariadb-bin.000018/67582355 (io.debezium.connector.mysql.BinlogReader:1054)[2019-07-19 09:38:05,247] TRACE Received event: Event{header=EventHeaderV4{timestamp=1562642991000, eventType=QUERY, serverId=1, headerLength=19, dataLength=356, nextPosition=95707350, flags=8}, data=QueryEventData{threadId=0, executionTime=0,errorCode=0, database='', sql='# Dummy event replacing event type 160 that slave cannot handle.

上面的日志给出了具体出错的binlog所在的文件和位置.dump出具体的binlog内容,查看

# 开始位置必须是我们日志中的位置,结束位置根据你期望看到的日志大小,增加一个值.这里我增加了2000
mysqlbinlog --start-position="67582355" --stop-position="67584355" /opt/data/mariadb-bin.000018

#bin log 内容如下

root@mariadb-1-598c45cfb9-kf6rt:/var/log/mysql# mysqlbinlog --start-position="67582355" --stop-position="67585355" /var/log/mysql/mariadb-bin.000018
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#190709  3:31:18 server id 1  end_log_pos 256 CRC32 0x9f4535ee  Start: binlog v 4, server v 10.3.10-MariaDB-1:10.3.10+maria~bionic-log created 190709  3:31:18
BINLOG '
hgokXQ8BAAAA/AAAAAABAAAAAAQAMTAuMy4xMC1NYXJpYURCLTE6MTAuMy4xMCttYXJpYX5iaW9u
aWMtbG9nAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAA5AAEGggAAAAICAgCAAAACgoKAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAEEwQADQgICAoKCgHuNUWf
'/*!*/;
# at 67582355
#190710  8:52:12 server id 1  end_log_pos 67584614 CRC32 0x0cc5dedc     Query   thread_id=2003941       exec_time=0     error_code=0
use `fact_contract`/*!*/;
SET TIMESTAMP=1562748732/*!*/;
SET @@session.pseudo_thread_id=2003941/*!*/;
SET @@session.foreign_key_checks=0, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1, @@session.check_constraint_checks=1/*!*/;
SET @@session.sql_mode=1411383304/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8mb4 *//*!*/;
SET @@session.character_set_client=45,@@session.collation_connection=45,@@session.collation_server=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
CREATE TABLE `instance`  (
  `id` varchar(32) CHARACTER SET utf8 COLLATE utf8_general_ci NOT NULL COMMENT '主键ID',
  `name` varchar(255) CHARACTER SET utf8 COLLATE utf8_general_ci NULL DEFAULT NULL COMMENT '合同名称',
  `templateId` varchar(32) CHARACTER SET utf8 COLLATE utf8_general_ci NULL DEFAULT NULL COMMENT '合同模板ID',
  `contractNo` varchar(64) CHARACTER SET utf8 COLLATE utf8_general_ci NULL DEFAULT NULL COMMENT '合同编号',
  `docNo` varchar(64) CHARACTER SET utf8 COLLATE utf8_general_ci NULL DEFAULT NULL COMMENT '单据编号',
  `docType` varchar(32) CHARACTER SET utf8 COLLATE utf8_general_ci NULL DEFAULT NULL COMMENT '单据类型（\"0 订单\n1 结算票\n2 发票\n3 付款承诺\n4 其他\"）',
  `ccy` varchar(32) CHARACTER SET utf8 COLLATE utf8_general_ci NULL DEFAULT NULL COMMENT '币种\r\n',
  `parAmt` varchar(24) CHARACTER SET utf8 COLLATE utf8_general_ci NULL DEFAULT NULL COMMENT '票面金额\r\n',
  `accountReceiveAmt` varchar(24) CHARACTER SET utf8 COLLATE utf8_general_ci NULL DEFAULT NULL COMMENT '应收账款金额\r\n',
  `accountBegDate` datetime(0) NULL DEFAULT NULL COMMENT '账款起始日\r\n',
  `accountEndDate` datetime(0) NULL DEFAULT NULL COMMENT '账款到期日\r\n',
  `payTerm` varchar(32) CHARACTER SET utf8 COLLATE utf8_general_ci NULL DEFAULT NULL COMMENT '付款条件\r\n',
  `draftDate` datetime(0) NULL DEFAULT NULL COMMENT '发票日\r\n',
  `inspectionDate` datetime(0) NULL DEFAULT NULL COMMENT '验货日\r\n',
  `payDays` varchar(24) CHARACTER SET utf8 COLLATE utf8_general_ci NULL DEFAULT NULL COMMENT '付款天数\r\n',
  `createdBy` varchar(64) CHARACTER SET utf8 COLLATE utf8_general_ci NULL DEFAULT NULL COMMENT '记录创建人账号ID',
  `createdAt` datetime(0) NULL DEFAULT current_timestamp() COMMENT '记录创建时间',
  `modifiedBy` varchar(64) CHARACTER SET utf8 COLLATE utf8_general_ci NULL DEFAULT NULL COMMENT '记录修改人账号ID',
  `modifiedAt` datetime(0) NULL DEFAULT NULL COMMENT '记录修改时间',
  PRIMARY KEY (`id`) USING BTREE
) ENGINE = InnoDB CHARACTER SET = utf8 COLLATE = utf8_general_ci COMMENT = '合同实例表' ROW_FORMAT = Dynamic
/*!*/;
# at 67584614
#190710  8:52:12 server id 1  end_log_pos 67584656 CRC32 0x8b622d76     GTID 0-1-1455487 ddl
/*!100101 SET @@session.skip_parallel_replication=0*//*!*/;
/*!100001 SET @@session.gtid_domain_id=0*//*!*/;
/*!100001 SET @@session.server_id=1*//*!*/;
/*!100001 SET @@session.gtid_seq_no=1455487*//*!*/;
# at 67584656

可以看到是一个数据库创建语句,里面有字段datetime(0), 之前一直创建表的时候,使用的datetime的时候, 都是直接使用,没有使用过datetime(0)这种写法. 使用上面的SQL语句执行,发现可以创建成功,同时CDC报错.验证了之前的CDC的错误.

寻找相关资料,发现Mysql中支持这种写法,相关链接.括号里面的值表示时间的秒后面保留的微秒的精度,取值范围是0-6,如果为0的话,可以默认不写.

# create table
mysql>CREATE TABLE t1 (t TIME(3), dt DATETIME(0),dt1 DATETIME(1),dt2 DATETIME(2), dt3 DATETIME(3), dt4 DATETIME(4), dt5 DATETIME(5), dt6 DATETIME(6));

mysql> desc t1;
+-------+-------------+------+-----+---------+-------+
| Field | Type        | Null | Key | Default | Extra |
+-------+-------------+------+-----+---------+-------+
| t     | time(3)     | YES  |     | NULL    |       |
| dt    | datetime    | YES  |     | NULL    |       |
| dt1   | datetime(1) | YES  |     | NULL    |       |
| dt2   | datetime(2) | YES  |     | NULL    |       |
| dt3   | datetime(3) | YES  |     | NULL    |       |
| dt4   | datetime(4) | YES  |     | NULL    |       |
| dt5   | datetime(5) | YES  |     | NULL    |       |
| dt6   | datetime(6) | YES  |     | NULL    |       |
+-------+-------------+------+-----+---------+-------+
8 rows in set (0.05 sec)

mysql> select * from t1;
+--------------+---------------------+-----------------------+------------------------+-------------------------+--------------------------+---------------------------+----------------------------+
| t            | dt                  | dt1                   | dt2                    | dt3                     | dt4                      | dt5                       | dt6                        |
+--------------+---------------------+-----------------------+------------------------+-------------------------+--------------------------+---------------------------+----------------------------+
| 14:18:44.000 | 2019-07-19 14:18:46 | 2019-07-19 14:18:49.0 | 2019-07-19 14:18:51.00 | 2019-07-19 14:18:52.000 | 2019-07-19 14:18:54.0000 | 2019-07-19 14:18:57.00000 | 2019-07-19 14:19:00.000000 |
+--------------+---------------------+-----------------------+------------------------+-------------------------+--------------------------+---------------------------+----------------------------+
1 rows in set (0.04 sec)

既然Mysql支持,那就是Debezium解析的时候,逻辑不严谨报错了.查看Debezium的代码.我们当前使用的Debezium的版本是v0.94.Final.

追踪代码,发现在Debeziume的代码中,MySqlDefaultValuePreConverter类中,会对默认值进行转换,当为时间类型的时候,使用了JDK中的DateTimeFormatterBuilder,该类在format的时候,可以指定保留的微秒的位数.具体代码如下:

private DateTimeFormatter timestampFormat(int length) {
        final DateTimeFormatterBuilder dtf = new DateTimeFormatterBuilder()
                .appendPattern("yyyy-MM-dd HH:mm:ss");
        if (length !=-1) {
            dtf.appendFraction(ChronoField.MICRO_OF_SECOND, 0, length, true);
        }
        return dtf.toFormatter();
    }

我们给datetime(0)的时候,该方法中的length值为0,而次方法中只进行length不等于-1的判断,所以会执行appendFraction方法

public DateTimeFormatterBuilder appendFraction(
            TemporalField field, int minWidth, int maxWidth, boolean decimalPoint) {
        appendInternal(new FractionPrinterParser(field, minWidth, maxWidth, decimalPoint));
        return this;
    }

FractionPrinterParser(TemporalField field, int minWidth, int maxWidth, boolean decimalPoint) {
            Objects.requireNonNull(field, "field");
            if (field.range().isFixed() == false) {
                throw new IllegalArgumentException("Field must have a fixed set of values: " + field);
            }
            if (minWidth < 0 || minWidth > 9) {
                throw new IllegalArgumentException("Minimum width must be from 0 to 9 inclusive but was " + minWidth);
            }
            if (maxWidth < 1 || maxWidth > 9) {
                throw new IllegalArgumentException("Maximum width must be from 1 to 9 inclusive but was " + maxWidth);
            }
            if (maxWidth < minWidth) {
                throw new IllegalArgumentException("Maximum width must exceed or equal the minimum width but " +
                        maxWidth + " < " + minWidth);
            }
            this.field = field;
            this.minWidth = minWidth;
            this.maxWidth = maxWidth;
            this.decimalPoint = decimalPoint;
        }

该方法在length < 1 的时候会报错,从而导致connector悬起来了.发现在Debezium在后面的版本中,即v0.9.5.Final中已经修复了该问题,修复代码如下:

private DateTimeFormatter timestampFormat(int length) {
        final DateTimeFormatterBuilder dtf = new DateTimeFormatterBuilder()
                .appendPattern("yyyy-MM-dd HH:mm:ss");
        if (length > 0) {
            dtf.appendFraction(ChronoField.MICRO_OF_SECOND, 0, length, true);
        }
        return dtf.toFormatter();
    }

所以在v0.9.5.Final及以后的版本,应该不会出现该问题.

参考

Published

Category

database

Tags