cana_1.1.0_tsdb_功能踩坑

最新推荐文章于 2024-04-07 20:36:50 发布

夜月行者

最新推荐文章于 2024-04-07 20:36:50 发布

阅读量5.7k

点赞数 5

分类专栏： canal

本文链接：https://blog.csdn.net/u013200380/article/details/85137090

版权

canal 专栏收录该内容

3 篇文章 2 订阅

订阅专栏

文章目录

背景

在上次canal_1.0.26 爆出bug太多而无法使用的情况下，我们对canal做了一次推荐的升级，当时是canal_1.1.0版本
同时，在这个版本中canal完成了稳定的tsdb的功能(1.0.26tsdb功能有bug)，于是我们也开启了这个功能。

实际在线上使用的是ha模式(tsdb使用的是本地的h2数据库)，使用过程中发现还是很容易出现在ddl新增列等操作中如果在ddl之后发生了ha切换，那么有一定的概率出现了数据无法解析，报错为


2018-12-19 20:19:24.651 [destination = xm_search , address = /10.120.66.42:3306 , EventParser] ERROR com.alibaba.otter.canal.common.alarm.LogAlarmHandler - destination:xm_search[com.alibaba.otter.canal.parse.exception.CanalParseException: com.alibaba.otter.canal.parse.exception.CanalParseException: parse row data failed.
Caused by: com.alibaba.otter.canal.parse.exception.CanalParseException: parse row data failed.
Caused by: com.alibaba.otter.canal.parse.exception.CanalParseException: column size is not match for table:xm_search.user,5 vs 4

这段异常中的5是实际的数据列数，4是canal中存储的metadata中该表的列，在实际中发现数据确实为5，也就是切换之后canal没有获取到真正的最新的metadata。按照官方的介绍，应该是没问题的，但是我们的线上环境反复出现问题，所拉出来总结一下。

理解canal tsdb的功能需要先看懂官方对tsdb的介绍和实现
https://github.com/alibaba/canal/wiki/TableMetaTSDB

测试过程

测试的环境是接着之前同事的测试进行的，是在 xm_search 库中新建了一张表 user 用来测试(该表为同事所建，已经在周三做过一些测试，能够大概率的复现ddl之后canal HA 切换后不正常，但是不能准确和预期一致)

1.测试开始时，表结构为

mysql> describe user;
+-------+---------------------+------+-----+---------+----------------+
| Field | Type | Null | Key | Default | Extra |
+-------+---------------------+------+-----+---------+----------------+
| id | bigint(20) unsigned | NO | PRI | NULL | auto_increment |
| name | varchar(20) | NO | | NULL | |
| age | int(3) | YES | | NULL | |
+-------+---------------------+------+-----+---------+----------------+
3 rows in set (0.02 sec)

需要注意的是:此时test环境中的xm-indexer(canal的client 端)已经部署为不含该表的filter模式(使用的是客户端指定filter)

2.此时对user 表做了alter 操作

alert table user add colum update_at timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP COMMENT '修改时间'


mysql> describe user;
+-----------+---------------------+------+-----+-------------------+-----------------------------+
| Field | Type | Null | Key | Default | Extra |
+-----------+---------------------+------+-----+-------------------+-----------------------------+
| id | bigint(20) unsigned | NO | PRI | NULL | auto_increment |
| name | varchar(20) | NO | | NULL | |
| age | int(3) | YES | | NULL | |
| update_at | timestamp | NO | | CURRENT_TIMESTAMP | on update CURRENT_TIMESTAMP |
+-----------+---------------------+------+-----+-------------------+-----------------------------+
4 rows in set (0.01 sec)

3.这个时候，我做了一次dml操作，修改age字段


mysql> update user set age=age+3 where id<5;
Query OK, 4 rows affected (0.02 sec)
Rows matched: 4 Changed: 4 Warnings: 0

然后将 xm-indexer重新上线，这次包含了对user 表的订阅
这个时候发现canal01开始报错


2018-12-19 15:19:24.651 [destination = xm_search , address = /10.120.66.42:3306 , EventParser] ERROR com.alibaba.otter.canal.common.alarm.LogAlarmHandler - destination:xm_search[com.alibaba.otter.canal.parse.exception.CanalParseException: com.alibaba.otter.canal.parse.exception.CanalParseException: parse row data failed.
Caused by: com.alibaba.otter.canal.parse.exception.CanalParseException: parse row data failed.
Caused by: com.alibaba.otter.canal.parse.exception.CanalParseException: column size is not match for table:xm_search.user,4 vs 3

这个过程(从alter到dml)canal是一直在运行过程中的，问题显得有些诡异。后来分析问题时觉得是因为第一次(同事测试的时候) xm-indexer(canal客户端)订阅了user库，后面又取消了订阅，增加列的ddl是在取消订阅以后增加的，后面客户端的filter变更又开始订阅时，canal中的 schema meta 仍然是第一次订阅时候记录的数据。所以会出现无法解析的问题。

阶段二的测试是，stop canal01,让其通过ha模式切换到canal02上面，这个时候理论上应该是会报错，因为canal02上缺少update_at这一列，但是奇怪的是切换到02上面并没有报错，这个时候将canal01重启，再切换到canal01上，仍然报错和之前的是一样，就是meta data 为旧数据，唯一的解释就是canal不会更新其meta data, 仍然使用h2中记录的meta data, 但是为什么切换到canal02上的时候又是正常的呢？百思不得其解，后来在翻看xm-indexer的日志中无意的发现其消费日志记录如下(canal02的状态下)

user 表ddl add column (此时连接的为canal01)------->stop canal01 ------->成功切换到canal02------>mysql dml 操作,canal并没有报错

2018-12-1920: 22: 37.984Thread-7INFOcom.kk.search.indexer.nrt.Canal: 106canal>>>kafka: xm_search.user,
{
  "op": 2,
  "update_time": 1545222157000,
  "before": {
    "phone": "2018-12-19 20:18:48",
    "name": "wanghui",
    "id": "1",
    "age": "113"
  },
  "data_mark": "7fc43375-6348-47fc-b317-01bced4e92ef",
  "after": {
    "phone": "2018-12-19 20:22:37",
    "name": "wanghui",
    "id": "1",
    "age": "116"
  }
}

可以看到的是这里并没有update_at字段，而是有一个phone字段容纳了原来的update字段的值，看到这里，恍然大悟，一切都能解释的通了,canal在重启当中如果tsdb 对应的数据库中有对应的meta data (表结构定义)时就会使用tsdb中的数据，否则会去主库(mysql master)中拉取一份。但是canal有一个问题是，当meta data中的列数比实际中的数据的列数多的时候并不会报错，只有meta data中的数据比实际中的少的时候才有可能会报错。这样的话就会出现数据解析错乱的情况。

1.canal tsdb中的meta data 和mysql中的数据的列数一致的话，不会报错，不论实际上的列名是否完全一致，也就是你增加一列，再减少一列的时候如果canal发生了切换，还是可以正常解析的，但是实际上信息是有误的。
2.canal tsdb中的meta data 比mysql中的数据的列数要更多，这个时候也是不会报错的，正常解析
3.canal tsdb中的meta data 比mysql中的数据的列数少，这个时候canal的解析会报错

可以想象，这种情况下，如果使用的表变更频繁的话是一种很危险情况，希望canal官方能够将这一块儿文档再完善一下。
后面将本地的h2数据库换成中心式的mysql，则没有再出现类似的问题。

同时，测试表明，在canal发生问题的时候还是会丢数据，这一块儿也需要注意，client端在zk中的数据是canal来管理的，这个地方的canal在报错的情况下依然会更新对应的binlog位置信息，导致出错。

上次异常总体回顾

问题表现：

1.下午14:10:50左右出现indexer项目无法消费cannal数据的情况，此时canal为search-01 机器
日志中报错信息为

主要是因为h2本地库被删除导致
2018-12-12 14:10:10.522 [destination = kuaikan , address = /10.9.5.43:3306 , EventParser] ERROR c.a.o.c.p.inbound.mysql.rds.RdsBinlogEventParserProxy - dump address 10.9.5.43/10.9.5.43:3306 has an error, retrying. caused by
com.alibaba.otter.canal.parse.exception.CanalParseException: com.alibaba.otter.canal.parse.exception.CanalParseException: apply history to db failed caused by : SqlMapClient operation; bad SQL grammar []; nested exception is com.ibatis.common.jdbc.exception.NestedSQLException:
--- The error occurred in spring/tsdb/sql-map/sqlmap_history.xml.
--- The error occurred while executing update.
--- Check the          insert into meta_history (            gmt_create,gmt_modified,destination,binlog_file,binlog_offest,binlog_master_id,binlog_timestamp,use_schema,sql_schema,sql_table,sql_text,sql_type,extra              )         values(CURRENT_TIMESTAMP,CURRENT_TIMESTAMP,?,?,?,?,?,?,?,?,?,?,?)     .
--- Check the SQL Statement (preparation failed).
--- Cause: org.h2.jdbc.JdbcSQLException: Table "META_HISTORY" not found; SQL statement:
         insert into meta_history (            gmt_create,gmt_modified,destination,binlog_file,binlog_offest,binlog_master_id,binlog_timestamp,use_schema,sql_schema,sql_table,sql_text,sql_type,extra              )         values(CURRENT_TIMESTAMP,CURRENT_TIMESTAMP,?,?,?,?,?,?,?,?,?,?,?)      [42102-196]
Caused by: com.alibaba.otter.canal.parse.exception.CanalParseException: apply history to db failed caused by : SqlMapClient operation; bad SQL grammar []; nested exception is com.ibatis.common.jdbc.exception.NestedSQLException:

....

canal试图通过重启来进行自我修复,他重启了parser组件
2018-12-12 14:10:23.970 [destination = kuaikan , address = /10.9.5.43:3306 , EventParser] WARN  c.a.o.c.p.inbound.mysql.rds.RdsBinlogEventParserProxy - prepare to find start position just last position
 {"identity":{"slaveId":-1,"sourceAddress":{"address":"10.9.5.43","port":3306}},"postion":{"gtid":"","included":false,"journalName":"mysql-bin.005416","position":245325838,"serverId":701143306,"timestamp":1544595010000}}


...


查询快照的时候出错
2018-12-12 14:10:23.972 [destination = kuaikan , address = /10.9.5.43:3306 , EventParser] ERROR c.a.o.c.p.inbound.mysql.rds.RdsBinlogEventParserProxy - dump address 10.9.5.43/10.9.5.43:3306 has an error, retrying. caused by
com.alibaba.otter.canal.parse.exception.CanalParseException: apply failed caused by : SqlMapClient operation; bad SQL grammar []; nested exception is com.ibatis.common.jdbc.exception.NestedSQLException:
--- The error occurred in spring/tsdb/sql-map/sqlmap_snapshot.xml.
--- The error occurred while executing query.
--- Check the       select             a.id as id,a.gmt_create as gmtCreate,a.gmt_modified as gmtModified,   a.destination as destination,a.binlog_file as binlogFile,a.binlog_offest as binlogOffest,a.binlog_master_id as binlogMasterId,a.binlog_timestamp as binlogTimestamp,a.data as data,a.extra as extra                             from meta_snapshot a         where destination = ? and binlog_timestamp < ?         order by binlog_timestamp desc,id desc         limit 1              .
--- Check the SQL Statement (preparation failed).
--- Cause: org.h2.jdbc.JdbcSQLException: Table "META_SNAPSHOT" not found; SQL statement:
      select             a.id as id,a.gmt_create as gmtCreate,a.gmt_modified as gmtModified,   a.destination as destination,a.binlog_file as binlogFile,a.binlog_offest as binlogOffest,a.binlog_master_id as binlogMasterId,a.binlog_timestamp as binlogTimestamp,a.data as data,a.extra as extra                             from meta_snapshot a         where destination = ? and binlog_timestamp < ?         order by binlog_timestamp desc,id desc         limit 1               [42102-196]

2.同事进行了一次canal的切换，切换完成以后 server02上canal 报出表数据解析异常的错误（报错信息是拿到的数据字段数和 canal中的表的元数据定义的字段数量不一致）


2018-12-12 14:22:41.120 [destination = kuaikan , address = /10.9.5.43:3306 , EventParser] ERROR c.a.o.c.p.inbound.mysql.rds.RdsBinlogEventParserProxy - dump address 10.9.5.43/10.9.5.43:3306 has an error, retrying. caused by
com.alibaba.otter.canal.parse.exception.CanalParseException: com.alibaba.otter.canal.parse.exception.CanalParseException: parse row data failed.
Caused by: com.alibaba.otter.canal.parse.exception.CanalParseException: parse row data failed.
Caused by: com.alibaba.otter.canal.parse.exception.CanalParseException: column size is not match for table:kuaikan.topic,25 vs 23

3.后面同事再次进行了一次切换，canal切回search-01,数据消费正常。

这中间在第三步能够正确恢复的诀窍在于同事埋了一个坑，就是他把h2文件早就做了rm操作。
之所以做了一次rm操作，主要是因为cannal1.1.0中目前存在的一个小bug (这里)[https://github.com/alibaba/canal/issues/1100]
但是操作完以后应该讲canal进行一次重启的。

结论

基于canal1.1.0
在使用HA功能的同时，如果开启tsdb的话，一定要将tsdb设置为集中式的，也就是不要使用本地的h2了，而是使用集中化的mysql数据库，保证两台canal连接的是同一个数据库。这样的话才能够满足在进行DDL和HA切换的时候不会出现异常。

tsdb的mysql设置如下


canal.instance.tsdb.enable = true
canal.instance.tsdb.dir = ${canal.file.data.dir:../conf}/${canal.instance.destination:}
canal.instance.tsdb.url = jdbc:mysql://192.7.4.113:3306/canal_config_test?useSSL=false
canal.instance.tsdb.dbUsername = canal_config_rw
canal.instance.tsdb.dbPassword = ush2sdfsI