基于数据库Binlog 的业务系统操作日志实现方案（阿里中间件Canal）

针对一些重要的业务数据进行增删改查的时候，我们希望记录一下用户的操作行为，以便发生问题时能及时的找到依据，这种日志就是业务系统的操作日志，只关键解决的是用户操作行为的日志问题，不是泛指所有的日志业务，不是针对方便问题定位的日志和那些业务的数据传递的日志。

下文的观点方向都是旨在面向业务系统的操作日志 对比两种方案实现：

基于AOP（切面）传统的实现方案

• 优点：实现思路简单；
• 缺点：增加数据库的负担（因为要查询旧数据），强依赖前端的传参（旧数据不查询就通过传参的方式），不方便拓展，不支持批量操作，不支持多表关联；

基于数据库Binlog

• 优点：解除了数据新旧变化的耦合，支持批量操作，方便多表关联拓展，不依赖开发语言（因为是依赖数据库的 日志，所有和语言没有特别大关系）；
• 缺点：数据库表设计需要统一的约定（tracedid）；

Binlog 日志实现方案解决的spring -aop在是显示数据前后的变化的痛点问题

spring-aop在数据变更方面，一直没有较好的实现方式，比如数据在变更前是多少，变更后是多少。spring-aop方案也是大部分中小企业的首选实现方案，但是在一些金融领域以及erp相关系统，对操作日志记录明细要求极高，常见技术方案很难满足。

以我们以前实现的一套方案来说，基于数据变更的记录方式不仅要和需求方约定好模板（上百个字段的不可能都做展示和记录），也要和前端做一些约定，比如在修改之前的值是多少，修改后的值是多少，如下代码客官请看：

    @Valid
    @NotNull(message = "新值不能为空")
    @UpdateNewDataOperationLog
    private T newData;      //设置两个属性来完成 前后数据变化问题

    @Valid
    @NotNull(message = "旧值不能为空")
    @UpdateOldDataOperationLog
    private T oldData;

存在的问题：

• 1.旧值如果不多查询一次数据库则需要依赖前端把旧值封装到oldData对象中，很有可能已经不是修改前的值；// 时效性导致的 数据变化安全问题
• 2.无法处理批量的List数据； 
• 3.不支持多表操作；

利用canal采集和解析业务库的binlog日志并投递到kafka中，解析后的记录中记录了当前操作的操作类型，如属于删除、修改、新增,和新旧值的记录，格式如下：

{"data":[{"id":"122158992930664499","bill_type":"1","create_time":"2020-04-2609:15:13","update_time":"2020-04-2613:45:46","version":"2","trace_id":"exclude-f04ff706673d4e98a757396efb711173"}],
"database":"yl_spmibill_8",
"es":1587879945200,
"id":17161259,
"isDdl":false,
"mysqlType":{"id":"bigint(20)",
"bill_type":"tinyint(2)",
"create_time":"timestamp",
"update_time":"timestamp",
"version":"int(11)",
"trace_id":"varchar(50)"},
"old":[{"update_time":"2020-04-2613:45:45",
"version":"1",
"trace_id":"exclude-36aef98585db4e7a98f9694c8ef28b8c"}],
"pkNames":["id"],"sql":"",
"sqlType":{"id":-5,"bill_type":-6,"create_time":93,"update_time":93,"version":4,"trace_id":12},     //
"table":"xxx_transfer_bill_117",
"ts":1587879945698,"type":"UPDATE"}

经过处理完binlon日志转换后的操作日志，如下：

  {
 "id":"120716921250250776",
 "relevanceInfo":"XX0000097413282,",
 "remark":"签收财务网点编码由【】改为【380000】，
  签收网点名称由【】改为【泉州南安网点】，签收网点code由【】改为【2534104】，运单状态code由【204】改为【205】，签收财务网点名称由【】改为【福建代理区】，签收网点id由【0】改为【461】，签收标识,1是，0否由【0】改为【1】，签收时间由【null】改为【2020-04-24 21:09:47】，签收财务网点id由【0】改为【400】，",
 "traceId":"120716921250250775"
  }

可以看到对业务操作的行为进行很细化输出。

Binlog及ReDolog

Binlog binary log 的缩写，为二进制日志，是逻辑上的日志，记录着数据在行的值是多少，主要目的是复制和恢复。

二进制日志是在存储引擎的上层产生的，不管是什么存储引擎，对数据库进行了修改都会产生二进制日志。而redo log是innodb层产生的，只记录该存储引擎中表的修改。并且二进制日志先于redo log被记录。

 Mysql 主从复制：在master开启binlog ，master把它的二进制日志传递给slaves达到 主从数据一致的目的，复制时直接复制行的数值。（也就是我们此次要用到的功能）。

数据恢复：使用mysqlbinlog 工具来恢复数据

ReDo log   

redo log是在物理格式上的日志，它记录的是数据库中每个页的修改。

redo log通常是物理日志，记录的是数据页的物理修改，而不是某一行或某几行修改成怎样怎样，它用来恢复提交后的物理数据页(恢复数据页，且只能恢复到最后一次提交的位置)。

两者数据修改上的区别:

二进制日志只在每次事务提交的时候一次性写入缓存中的日志"文件"(对于非事务表的操作，则是每次执行语句成功后就直接写入)。而redo log在数据准备修改前写入缓存中的redo log中，然后才对缓存中的数据执行修改操作；而且保证在发出事务提交指令时，先向缓存中的redo log写入日志，写入完成后才执行提交动作

感兴趣的小伙伴可以看详细的 ↓

redo log和二进制日志的区别

方案实现的原理

利用mysql 可以主从分离，master 产生的binlog日志记录了所有的ddl、dml（除了数据查询语句select、show等）操作语句，Master同过将二进制日志传递到slaves 来达到主从的数据保持一致的目的。

如果我们可以监听master -》伪造成一个slaves来接受master传输的binlog 并且解析binlog日志，就可以得到实时的日志操作，Canal就是实现这个binlog功能的同步工具。

方案实现的细节

使用binlog可以去得到mysql 变更的日志，那Canal怎么去解析的呢

首先开启mysql 二进制日志模式 ，在my.cnf 中增加 windows 里增加 my.ini配置。 

#配置binlog日志的存放路径为/var/lib/mysql目录，文件以mysql-bin开头    

log-bin=/var/lib/mysql/mysql-bin

# 配置mysql中每一行记录的变化都会详细记录下来

binlog-format=ROW

# 配置当前机器器的服务ID（如果是mysql集群，不能重复）

server_id=1

开启binlog 在本机中查看产生的 dml 的改动日志。

sql 语句

--查看 binlog 的配置情况-- show variables like '%log_bin%';

--查看缓存数据存放的位置-- show variables like '%datadir%';

-- 查看事件列表-- show binary logs;

--查看具体一个 事件-- show binlog events IN 'binlog.000003';

模拟进行一次insert  插入操作时 file_size 变大

一次插入操作 log 进行以下几次的变化 从19890 -》20219

安装 canal ，为canal的server端 ，配置instance.properties 会填入 要监控的mysqll master 连接地址 及 用户名 密码  可以配置kafka 的出口。客户端去请求server canal  解析数据。

安装 canal 

       配置 canal的server端环境 ，配置canal.properties、及关键的instance.properties 会填入 要监控的mysql master 连接地址 及 用户名 密码  可以配置kafka 的出口。客户端去请求server canal  解析数据。

一：解压下载好的 canal.deployer-1.0.25.tar.gz  在canal 目录下的 /conf/example中编辑 instance.properties 配置要监听的 master 数据库 配置连接地址、 用户名和密码 及编码集

canal.instance.master.address=127.0.0.1:3306

canal.instance.dbUsername=root canal.instance.dbPassword=xxxx  #canal.instance.defaultDatabaseName=project  //设置默认监听的数据库 不配置则监听所有的数据库 canal.instance.connectionCharset=UTF-8

二 ：在bin目录下 

sh startup.sh 命令去启动，sh stop.sh 命令去关闭

三：在 logs/example/ 下的 example.log 去查看日志

以下 说明启动成功

2020-08-04 17:07:14.132 [main] INFO c.a.o.c.i.spring.support.PropertyPlaceholderConfigurer - Loading properties file from class path resource [canal.properties] 2020-08-04 17:07:14.137 [main] INFO c.a.o.c.i.spring.support.PropertyPlaceholderConfigurer - Loading properties file from class path resource [example/instance.properties] 2020-08-04 17:07:14.353 [main] WARN o.s.beans.GenericTypeAwarePropertyDescriptor - Invalid JavaBean property 'connectionCharset' being accessed! Ambiguous write methods found next to actually used [public void com.alibaba.otter.canal.parse.inbound.mysql.AbstractMysqlEventParser.setConnectionCharset(java.nio.charset.Charset)]: [public void com.alibaba.otter.canal.parse.inbound.mysql.AbstractMysqlEventParser.setConnectionCharset(java.lang.String)] 2020-08-04 17:07:14.439 [main] INFO c.a.o.c.i.spring.support.PropertyPlaceholderConfigurer - Loading properties file from class path resource [canal.properties] 2020-08-04 17:07:14.440 [main] INFO c.a.o.c.i.spring.support.PropertyPlaceholderConfigurer - Loading properties file from class path resource [example/instance.properties] 2020-08-04 17:07:14.762 [main] ERROR com.alibaba.druid.pool.DruidDataSource - testWhileIdle is true, validationQuery not set 2020-08-04 17:07:15.137 [main] INFO c.a.otter.canal.instance.spring.CanalInstanceWithSpring - start CannalInstance for 1-example 2020-08-04 17:07:15.151 [main] INFO c.a.otter.canal.instance.core.AbstractCanalInstance - start successful....

四： 客户端可以监听到canal 服务端作为salve 收到的maser数据，客户端打印到控制台。

实现的效果

通过使用 新版本的 canal 1.1.4版本的 使用windows 端配置好一次成功运行。对mysql 数据变更的打印如下

当向canal 设置监听的master 库 插入的数据时 控制台打印：

insert into user_info  values(1,1,1) 

================> binlog[binlog.000003:22186] , name[test,user_info1] , eventType : INSERT        //binlog.000003 为binary log 的名称  22186 日志位置 显示类型为 insert

userid : 1 update=true name : 1 update=true age : 1 update=true

update user_info set name = 2 where userid =1         

================> binlog[binlog.000003:22490] , name[test,user_info1] , eventType : UPDATE -------> before  userid : 1 update=false name : 1 update=false age : 1 update=false -------> after userid : 1 update=false name : 2 update=true age : 1 update=false

可以看到对于记录系统业务上的操作有着直观的展示，不依靠数据库查询来完成数据对比，只需要增加一个 阿里云的插件，canal的客户端产生的日志可以输处到 Kafka中 进而被logstash收集。

特别注意每修改完 instance.properties ，请删除conf/example/  meta.dat

问题归纳：

一：xxxx - can't find start position for example  

原因:meta.dat 中保存的位点信息和数据库的位点信息不一致；导致canal抓取不到数据库的动作；

解决方案：删除meta.dat删除，再重启canal，问题解决；

二：xxxxxx -Client does not support authentication protocol requested by server;

 需要修改加密方式

// 查看用户 开放的host 及加密权限

select host,user,plugin,authentication_string from mysql.user; 

//修改数据库密码的加密方式

ALTER USER 'root'@'localhost' IDENTIFIED BY 'password' PASSWORD EXPIRE NEVER;

//修改密码 

ALTER USER 'root'@'localhost' IDENTIFIED WITH mysql_native_password BY '123';

FLUSH PRIVILEGES;

三：环境配置的没有问题 但控制台还是报错：

dump address /120.78.135.197:3306 has an error, retrying. caused by java.lang.IllegalArgumentException: null

2020-08-04 17:33:09.370 [destination = example , address = /172.18.0.2:3306 , EventParser] ERROR com.alibaba.otter.canal.common.alarm.LogAlarmHandler - destination:example[java.lang.NullPointerException at com.alibaba.otter.canal.parse.inbound.mysql.MysqlEventParser.findStartPositionInternal(MysqlEventParser.java:428) at com.alibaba.otter.canal.parse.inbound.mysql.MysqlEventParser.findStartPosition(MysqlEventParser.java:348) at com.alibaba.otter.canal.parse.inbound.AbstractEventParser$3.run(AbstractEventParser.java:164) at java.lang.Thread.run(Thread.java:748)

canal.properties中没有配置canal.instance.parser.parallelThreadSize=256默认好像是256，这里就是cpu核数的问题。

解决办法是更改虚拟机配置，设置成2个或以上cpu就能解决问题。通过对问题的分析，对于单cpu的物理机，无法通过修改cpu数量的情况，可以通过配置文件解决。 canal.instance.parser.parallelThreadSize = 1,解决即可，我的linux 学生机 是1G 的 添加上参数后还是不好用，后来在github 项目官网 看到了新版本对 mysql 8 密码加密方式的更新及优化 

额外记录一下用到的linux 命令

linux 查看指定端口的指令：

netstat -anp |gerp xxxport

查看全部监听的端口

netstat -nultp 

centos7 开放端口指令：

firewall-cmd --zone=public --add-port=5672/tcp --permanent 

firewall-cmd --reload

进入docker 容器

docker exec -it 容器名称 bash 

查看decker 容器中的 ip 及信息

docker  inspect  容器号87b427e832eb;

Docker的网络类型有三种：

• Bridge：桥接网络。默认情况下启动的Docker容器，都是使用Bridge，Docker安装时创建的桥接网络，每次Docker容器重启时，会按照顺序获取对应的IP地址，这个就导致重启下，Docker的IP地址就变了。
• None：无指定网络。使用 --network=none，Docker容器就不会分配局域网的IP。
• Host：主机网络。使用--network=host，此时，Docker容器的网络会附属在主机上，两者是互通的。例如，在容器中运行一个Web服务，监听8080端口，则主机的8080端口就会自动映射到容器中。

创建自定义网络：（设置固定IP）

docker network create --subnet=172.18.0.0/16 mynetwork

遇到的jvm的问题，自己的  1G centos 主机 运行着一个 springboot 项目 +docker 下的mysql 当我启动canal 服务时，出现了报错情况 如下

Java HotSpot(TM) Server VM warning: ignoring option MaxPermSize=128m; support was removed in 8.0 Java HotSpot(TM) Server VM warning: INFO: os::commit_memory(0xb6e00000, 805306368, 0) failed; error='Cannot allocate memory' (errno=12)

# There is insufficient memory for the Java Runtime Environment to continue. 关键这句话 # Native memory allocation (mmap) failed to map 805306368 bytes for committing reserved memory. # An error report file with more information is saved as: # /usr/local/Canal/bin/hs_err_pid14925.log

查看 hs_err_pid14925.log 文件 Memory: 4k page, physical 1882148k(70736k free), swap 0k(0k free)  0k没有内存可以使用 。

文章链接：

我们已经不用AOP做操作日志了！

canal使用记录

基于 Docker 结合 Canal 实现 MySQL 实时增量数据传输

阿里巴巴中间件canal的搭建和使用