更新MySql数据库一条记录时 创建时间也更新为update时的时间了!!
排查问题时发现一个不一致:一条数据的创建时间比日志中操作这条记录的时间还晚。
这种情况不是bug,就是穿越了。。。
问了下才了解,这种问题早就存在了,也不知道是什么原因。
也可能是中了魔法吧
之前的解决创建时间被更新莫名其妙的更新的办法是这样的:
更新前先把创建时间从库里查出来,然后更新时把创建时间再update为之前的创建时间
import lombok.extern.slf4j.Slf4j;
import org.springframework.stereotype.Service;
@Slf4j
@Service
public class TaskService {
/**
* 更新状态时,为确保记录的创建时间不在update时被更新,先查出历史gmtCreate值,然后再更新进去
*
* @param taskId
* @param status
* @param modifiedBy
* @return
*/
@Override
public boolean updateStatus(Long taskId, String status, String modifiedBy) {
log.info("更新状态开始 对账单id {} status {}", taskId, status);
Task originCs = this.getById(taskId); //先把创建时间查出来
Task task = new Task();
task.setId(taskId);
task.setStatus(status);
task.setGmtCreate(originCs.getGmtCreate()); //更新时把创建时间再更新更新成之前的值。。。
task.setModifiedBy(modifiedBy);
task.setGmtModified(new Timestamp(System.currentTimeMillis()));
boolean result = this.updateById(task);
log.info("更新状态结束 对账单id {} 状态 {}", taskId, status);
return result;
}
}
猜测
项目中用到的ORM框架是Mybatis-Plus
会不会是Mybatis-Plus有些特殊插件被开启,然后创建时间也被更新了?
估计之前的同学也是这样想的,框架代码那么多,还有6-7个同学参与开发,有不少就是来打个酱油写个需求就撤了,谁知道有没有加入什么魔法操作。所以这个问题就一直搁置在这了
复现
那先用笨办法,复现一下,把传的参数,update日志都打开,先看看情况
case:
step1:Mybatis-Plus输出执行sql的日志打印
logging.level.com.dao.mp.adapter.repository=debug
step2:按目前项目中的方式 新增一条记录。新增前,把请求参数打印出来
step3:更新step2中记录。更新前,把更新的参数打印出来 step4:打印更新后的记录值。 比对创建时间是否被更新了
import com.alibaba.fastjson2.JSON;
import com.dao.mp.MpIntroductionApplication;
import com.dao.mp.adapter.repository.task.domain.entity.Task;
import lombok.extern.slf4j.Slf4j;
import net.minidev.json.JSONValue;
import org.junit.jupiter.api.Test;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.boot.test.context.SpringBootTest;
import java.sql.Timestamp;
import java.util.List;
import java.util.concurrent.ThreadLocalRandom;
import java.util.concurrent.TimeUnit;
import static org.assertj.core.api.Assertions.assertThat;
@Slf4j
@SpringBootTest(classes = {MpIntroductionApplication.class})
class TaskServiceImplTest {
@Autowired
private TaskServiceImpl taskServiceImpl;
@Test
public void testSave() throws InterruptedException {
Task task = new Task();
task.setName(String.join("_", "任务", String.valueOf(ThreadLocalRandom.current().nextInt())));
Timestamp now = new Timestamp(System.currentTimeMillis());
task.setGmtCreate(now);
task.setGmtModified(now);
boolean saveResult = taskServiceImpl.save(task);
log.info("saveResult {} task {} ", saveResult, task);
task = taskServiceImpl.getById(task.getId());
Timestamp firstGmtCreate = task.getGmtCreate();
log.info("准备更新操作======");
TimeUnit.SECONDS.sleep(1);
Task entityUpdate = new Task();
entityUpdate.setId(task.getId());
entityUpdate.setName(task.getName() + "更新一下");
log.info("待更新的数据 entityUpdate {} ", JSON.toJSONString(entityUpdate));
boolean updateResult = taskServiceImpl.updateById(entityUpdate);
log.info(" updateResult {}", updateResult);
Task taskAfterUpdate = taskServiceImpl.getById(task.getId());
log.info("taskAfterUpdate {} ", JSON.toJSONString(taskAfterUpdate));
assertThat(taskAfterUpdate.getGmtCreate()).isEqualTo(firstGmtCreate);
}
}
复现了:创建时间又被更新了
2022-07-17 15:39:38.540 DEBUG 11203---[main]c.d.m.a.r.task.mapper.TaskMapper.insert:==>Preparing:INSERT INTO task(name,deleted,gmt_create,gmt_modified)VALUES(?,?,?,?)
2022-07-17 15:39:38.579 DEBUG 11203---[main]c.d.m.a.r.task.mapper.TaskMapper.insert:==>Parameters:任务_-1650571110(String),false(Boolean),2022-07-17 15:39:37.439(Timestamp),2022-07-17 15:39:37.439(Timestamp)
2022-07-17 15:39:38.594 DEBUG 11203---[main]c.d.m.a.r.task.mapper.TaskMapper.insert:<==Updates:1
2022-07-17 15:39:38.621 INFO 11203---[main]c.d.m.a.r.task.TaskServiceImplTest:saveResult true task Task(name=任务_-1650571110,deleted=false)
2022-07-17 15:39:38.624 DEBUG 11203---[main]c.d.m.a.r.t.m.TaskMapper.selectById:==>Preparing:SELECT id,name,deleted,gmt_create,gmt_modified FROM task WHERE id=?AND deleted=false
2022-07-17 15:39:38.624 DEBUG 11203---[main]c.d.m.a.r.t.m.TaskMapper.selectById:==>Parameters:1548483797471731720(Long)
2022-07-17 15:39:38.644 DEBUG 11203---[main]c.d.m.a.r.t.m.TaskMapper.selectById:<==Total:1
2022-07-17 15:39:38.652 INFO 11203---[main]c.d.m.a.r.task.TaskServiceImplTest:准备更新操作======
2022-07-17 15:39:39.753 INFO 11203---[main]c.d.m.a.r.task.TaskServiceImplTest:待更新的数据 entityUpdate{"gmtCreate":"2022-07-17T15:39:39.752+08:00","gmtModified":"2022-07-17T15:39:39.657+08:00","id":1548483797471731720,"name":"任务_-1650571110更新一下"}
2022-07-17 15:39:39.761 DEBUG 11203---[main]c.d.m.a.r.t.m.TaskMapper.updateById:==>Preparing:UPDATE task SET name=?,gmt_create=?,gmt_modified=?WHERE id=?AND deleted=false
2022-07-17 15:39:39.763 DEBUG 11203---[main]c.d.m.a.r.t.m.TaskMapper.updateById:==>Parameters:任务_-1650571110更新一下(String),2022-07-17 15:39:39.763(Timestamp),2022-07-17 15:39:39.657(Timestamp),1548483797471731720(Long)
2022-07-17 15:39:39.791 DEBUG 11203---[main]c.d.m.a.r.t.m.TaskMapper.updateById:<==Updates:1
2022-07-17 15:39:39.792 INFO 11203---[main]c.d.m.a.r.task.TaskServiceImplTest:updateResult true
2022-07-17 15:39:39.792 DEBUG 11203---[main]c.d.m.a.r.t.m.TaskMapper.selectById:==>Preparing:SELECT id,name,deleted,gmt_create,gmt_modified FROM task WHERE id=?AND deleted=false
2022-07-17 15:39:39.792 DEBUG 11203---[main]c.d.m.a.r.t.m.TaskMapper.selectById:==>Parameters:1548483797471731720(Long)
2022-07-17 15:39:39.794 DEBUG 11203---[main]c.d.m.a.r.t.m.TaskMapper.selectById:<==Total:1
2022-07-17 15:39:39.796 INFO 11203---[main]c.d.m.a.r.task.TaskServiceImplTest:taskAfterUpdate{"deleted":false,"gmtCreate":1658043580000,"gmtModified":1658043580000,"id":1548483797471731720,"name":"任务_-1650571110更新一下"}
org.opentest4j.AssertionFailedError:
expected:2022-07-17T15:39:37.000(java.sql.Timestamp)
but was:2022-07-17T15:39:40.000(java.sql.Timestamp)
Expected:2022-07-17T15:39:37.000(java.sql.Timestamp)
Actual:2022-07-17T15:39:40.000(java.sql.Timestamp)
<Click to see difference>
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at com.dao.mp.adapter.repository.task.TaskServiceImplTest.testSave(TaskServiceImplTest.java:48)
看输出的日志,更新的参数有些异常: 虽然没有在更新逻辑中setGmtCreate,但的确有gmtCreate的确被赋值并参与了更新。
2022-07-17 15:39:39.753INFO 11203---[main]c.d.m.a.r.task.TaskServiceImplTest:待更新的数据 entityUpdate{"gmtCreate":"2022-07-17T15:39:39.752+08:00","gmtModified":"2022-07-17T15:39:39.657+08:00","id":1548483797471731720,"name":"任务_-1650571110更新一下"}
2022-07-17 15:39:39.761DEBUG 11203---[main]c.d.m.a.r.t.m.TaskMapper.updateById:==>Preparing:UPDATE task SET name=?,gmt_create=?,gmt_modified=?WHERE id=?AND deleted=false
2022-07-17 15:39:39.763DEBUG 11203---[main]c.d.m.a.r.t.m.TaskMapper.updateById:==>Parameters:任务_-1650571110更新一下(String),2022-07-17 15:39:39.763(Timestamp),2022-07-17 15:39:39.657(Timestamp),1548483797471731720(Long)
2022-07-17 15:39:39.791DEBUG 11203---[main]c.d.m.a.r.t.m.TaskMapper.updateById:<==Updates:1
不过这个对象比较简单,不涉及逻辑ORM框架。 发现getGmtCreate和getGmtModified被重写。 结合这个问题,一下子就明白了:更新时没有对gmtCreate字段赋值,然后在get时
import com.baomidou.mybatisplus.annotation.IdType;
import com.baomidou.mybatisplus.annotation.TableField;
import com.baomidou.mybatisplus.annotation.TableId;
import lombok.Data;
import java.sql.Timestamp;
@Data
public class BasePO {
@TableId(type = IdType.AUTO)
protected Long id;
@TableField(value = "gmt_create")
protected Timestamp gmtCreate;
@TableField(value = "gmt_modified")
protected Timestamp gmtModified;
public Timestamp getGmtCreate() {
if (null == this.gmtCreate) {
/**
* 更新时,如果没有给gmtCreate[创建时间]字段赋值,则返回当前时间。
* 真相大白!!
*/
return new Timestamp(System.currentTimeMillis());
} else {
return this.gmtCreate;
}
}
public Timestamp getGmtModified() {
if (null == this.gmtModified) {
return new Timestamp(System.currentTimeMillis());
} else {
return this.gmtModified;
}
}
}
怎么改
直接把getGmtCreate方法中的逻辑去掉?
@Data
public class BasePO {
@TableId(type = IdType.AUTO)
protected Long id;
@TableField(value = "gmt_create")
protected Timestamp gmtCreate;
@TableField(value = "gmt_modified")
protected Timestamp gmtModified;
public Timestamp getGmtCreate() {
// if (null == this.gmtCreate) {
/**
* 更新时,如果没有给gmtCreate[创建时间]字段赋值,则返回当前时间。
* 真相大白!!
*/
// return new Timestamp(System.currentTimeMillis());
// } else {
return this.gmtCreate;
// }
}
public Timestamp getGmtModified() {
return this.gmtModified;
}
}
too young too simple too naive!!!
看看这个这个BasePO有多少子类。 从这个写法上看,是想抽象每次insert时setGmtTime的重复劳动。 那么,数据库中有些表的gmt_create字段没有设置默认值且是非空。
如果有,按上面的逻辑改后,这些表涉及到的新增操作就会报错。
查了下,果然有:
如果全面检查一遍,看看有没有上面这种情况的。 看了看这么多表,陷入了沉思:有没有更好的赋被值的办法, 譬如
public class BasePO {
public Timestamp getGmtCreate() {
/**
* 没有id时,才会给能gmtCreate设置当前时间
*/
if (null == this.gmtCreate && id == null) {
/**
* 更新时,如果没有给gmtCreate[创建时间]字段赋值,则返回当前时间。
* 真相大白!!
*/
return new Timestamp(System.currentTimeMillis());
} else {
return this.gmtCreate;
}
}
}
对sql比较熟悉的同学都知道,并不是所有的更新都是根据id的。where条件中可以写得很丰富,只要你想不到,没有写不出来的
基于当前项目的技术栈,MybatisPlus的自动填充与当前的场景很match。
填充原理是直接给entity的属性设置值!!!
注解则是指定该属性在对应情况下必有值,如果无值则入库会是null
MyBatis-Plus自动填充功能
最新的改动方案:
- POJO对象中的get方法的逻辑去掉,保持职责单一。把getGmtCreate和getGmtModified的判断逻辑去掉,直接返回两个字段的值
- 在gmtCreate和gmtModified增加使用自动填充的注解标志。
如下所示:
import com.baomidou.mybatisplus.annotation.FieldFill;
import com.baomidou.mybatisplus.annotation.IdType;
import com.baomidou.mybatisplus.annotation.TableField;
import com.baomidou.mybatisplus.annotation.TableId;
import lombok.Data;
import java.sql.Timestamp;
/**
* mybatis-subject
*
* @Auther: cheng.tang
* @Date: 2022/7/17 11:53 AM
* @Description:
*/
@Data
public class BasePO {
@TableId(type = IdType.AUTO)
protected Long id;
@TableField(value = "gmt_create", fill = FieldFill.INSERT)
protected Timestamp gmtCreate;
@TableField(value = "gmt_modified", fill = FieldFill.INSERT_UPDATE)
protected Timestamp gmtModified;
/**
* 保持单一职责,此方法只负责将返回gmtCreate字段的值
* @return
*/
public Timestamp getGmtCreate() {
return this.gmtCreate;
}
/**
* 保持单一职责,此方法只负责将返回gmtModified字段的值
* @return
*/
public Timestamp getGmtModified() {
return this.gmtModified;
}
}
- 增加自动填充值的逻辑。识别step2中的自动填充标识,并填充期望的值
import com.baomidou.mybatisplus.core.handlers.MetaObjectHandler;
import lombok.extern.slf4j.Slf4j;
import org.apache.ibatis.reflection.MetaObject;
import org.springframework.stereotype.Component;
import java.sql.Timestamp;
/**
* mybatis-subject
*
* @Auther: cheng.tang
* @Date: 2022/7/16 9:31 PM
* @Description:
*/
@Slf4j
@Component
public class MPAutoFillMetaObject implements MetaObjectHandler {
@Override
public void insertFill(MetaObject metaObject) {
/**
* fieldName 是java对象的名字
*/
setFieldValByName("deleted", false, metaObject);
Timestamp now = new Timestamp(System.currentTimeMillis());
setFieldValByName("gmtCreate", now, metaObject);
setFieldValByName("gmtModified", now, metaObject);
}
@Override
public void updateFill(MetaObject metaObject) {
Timestamp now = new Timestamp(System.currentTimeMillis());
setFieldValByName("gmtModified", now, metaObject);
}
}
done!
再跑下测试用例,看看通过:
通过!
2022-07-17 16:50:56.207 DEBUG 21367 --- [ main] c.d.m.a.r.task.mapper.TaskMapper.insert : ==> Preparing: INSERT INTO task ( name, deleted, gmt_create, gmt_modified ) VALUES ( ?, ?, ?, ? )\
2022-07-17 16:50:56.265 DEBUG 21367 --- [ main] c.d.m.a.r.task.mapper.TaskMapper.insert : ==> Parameters: 任务_-590247699(String), false(Boolean), 2022-07-17 16:50:55.127(Timestamp), 2022-07-17 16:50:55.127(Timestamp)
2022-07-17 16:50:56.290 DEBUG 21367 --- [ main] c.d.m.a.r.task.mapper.TaskMapper.insert : <== Updates: 1
2022-07-17 16:50:56.332 INFO 21367 --- [ main] c.d.m.a.r.task.TaskServiceImplTest : saveResult true task Task(name=任务_-590247699, deleted=false)
2022-07-17 16:50:56.340 DEBUG 21367 --- [ main] c.d.m.a.r.t.m.TaskMapper.selectById : ==> Preparing: SELECT id,name,deleted,gmt_create,gmt_modified FROM task WHERE id=? AND deleted=false
2022-07-17 16:50:56.341 DEBUG 21367 --- [ main] c.d.m.a.r.t.m.TaskMapper.selectById : ==> Parameters: 1548483797471731722(Long)
2022-07-17 16:50:56.369 DEBUG 21367 --- [ main] c.d.m.a.r.t.m.TaskMapper.selectById : <== Total: 1
2022-07-17 16:50:56.383 INFO 21367 --- [ main] c.d.m.a.r.task.TaskServiceImplTest : 准备更新操作======
2022-07-17 16:50:57.613 INFO 21367 --- [ main] c.d.m.a.r.task.TaskServiceImplTest : 待更新的数据 entityUpdate {"id":1548483797471731722,"name":"任务_-590247699更新一下"}
2022-07-17 16:50:57.620 DEBUG 21367 --- [ main] c.d.m.a.r.t.m.TaskMapper.updateById : ==> Preparing: UPDATE task SET name=?, gmt_modified=? WHERE id=? AND deleted=false
2022-07-17 16:50:57.622 DEBUG 21367 --- [ main] c.d.m.a.r.t.m.TaskMapper.updateById : ==> Parameters: 任务_-590247699更新一下(String), 2022-07-17 16:50:57.62(Timestamp), 1548483797471731722(Long)
2022-07-17 16:50:57.626 DEBUG 21367 --- [ main] c.d.m.a.r.t.m.TaskMapper.updateById : <== Updates: 1
2022-07-17 16:50:57.626 INFO 21367 --- [ main] c.d.m.a.r.task.TaskServiceImplTest : updateResult true
2022-07-17 16:50:57.627 DEBUG 21367 --- [ main] c.d.m.a.r.t.m.TaskMapper.selectById : ==> Preparing: SELECT id,name,deleted,gmt_create,gmt_modified FROM task WHERE id=? AND deleted=false
2022-07-17 16:50:57.627 DEBUG 21367 --- [ main] c.d.m.a.r.t.m.TaskMapper.selectById : ==> Parameters: 1548483797471731722(Long)
2022-07-17 16:50:57.629 DEBUG 21367 --- [ main] c.d.m.a.r.t.m.TaskMapper.selectById : <== Total: 1
2022-07-17 16:50:57.632 INFO 21367 --- [ main] c.d.m.a.r.task.TaskServiceImplTest : taskAfterUpdate {"deleted":false,"gmtCreate":1658047855000,"gmtModified":1658047858000,"id":1548483797471731722,"name":"任务_-590247699更新一下"}
小结&&经典实践
出现这个问题的初衷是想抽象对创建时间和修改时间重复赋值的重复操作。
解决这个问题有两个层面的解决办法:
方案1. 数据库层面,将创建时间和修改时间设置默认值并非空。
CREATE TABLE `task` (
`id` bigint unsigned NOT NULL AUTO_INCREMENT,
`name` varchar(100) NOT NULL COMMENT '任务名称',
`deleted` tinyint(1) NOT NULL COMMENT '1:已删除 0未删除',
`gmt_create` datetime NOT NULL DEFAULT CURRENT_TIMESTAMP COMMENT '创建时间',
`gmt_modified` datetime NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP COMMENT '修改时间',
PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=1 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci COMMENT='现实中的任务对应的结构化数据'
方案2. 应用层统一赋值。 赋默认值本身就是一件事,可以抽取出来。譬如使用MyBatis-Plus的自动填充特性
具体代码如上。需要两步,先声明式定义那些字段需要填充,再在MyBatis-Plus预留的扩展中按场景填入期望的值
将各个表中重复的属性抽取出公共基类,是个经典的实践。在本次的bug中属于没有用好。
各个业务模型映射到MySql表时,常见的6个基本属性:,
- id[主键id],
- gmt_create[创建时间],
- create_by[创建人],
- gmt_modified[更新时间],
- modified_by[更新人],
- deleted[逻辑删除标识 1已删除 0正常的数据]
不要被表象迷惑,按科学的方法将遇到的问题拆解,将问题固定到一个小的范围,就可以排除很多噪音。
先复现再根据复现步骤逐步排查是一个经典实践。
紧盯异常状态从开始到结束的数据流转,就可以顺藤摸瓜,找到根因。