问题

发现

美妙的一天，从在群里面被人艾特开始...

描述

celery定时任务修改了执行时间，页面展示的时间生效，但实际执行的时间不生效，还是使用按照原来的时间运行

代码

with transaction.atomic():
 # 更新PeriodicTask的字段
    if crontab_str := fields_kv.get('crontab', ''):
        logger.info(f'update field: {crontab_str=}')
        celery_model_operation.update_celery_crontab(
            celery_id=obj.celery_task.id,
            crontab_str=crontab_str,
        )
    if (is_enabled := fields_kv.get('is_enabled', None)) is not None:
        logger.info(f'update field: {is_enabled=}')
        celery_model_operation.update_celery_status(
            id=obj.celery_task.id,
            is_enabled=is_enabled,
        )
    if marker_name := fields_kv.get('marker_name', None):
        logger.info(f'update field: {marker_name=}')
        celery_task_obj = celery_model_operation.get_celery_obj_by_id(obj.celery_task.id)
        celery_task_obj.name = f'{obj.project_id}:{marker_name}'
        kwargs: dict = json.loads(obj.celery_task.kwargs)
        kwargs['marker_name'] = marker_name
        celery_task_obj.kwargs = json.dumps(kwargs)
        celery_task_obj.save()
    # 更新页面展示表的字段
    return super().partial_update(id, user_email, **fields_kv)

def get_celery_obj_by_id(id: int) -> PeriodicTask:
    return PeriodicTask.objects.get(id=id)


def update_celery_status(id: int, is_enabled: bool) -> None:
    celery_task_obj = get_celery_obj_by_id(id)
    celery_task_obj.enabled = is_enabled
    celery_task_obj.save()


def update_celery_crontab(celery_id: int, crontab_str: str) -> None:
    celery_task_obj = get_celery_obj_by_id(celery_id)
    crontab_obj = get_or_create_crontab_obj(crontab_str=crontab_str)
    celery_task_obj.crontab = crontab_obj
    celery_task_obj.save()

排查

问题确认

• 检查生产环境数据库，确实存在问题
• 生产环境界面操作，问题能复现

本地环境

手动接口检查

• 找到对应接口
• postman 调用接口，看日志
• 数据库检查数据
• 一切正常，完全没毛病

测试环境

页面操作

• 页面修改数据
• 检查前端入参
• 看接口日志
• 数据库检查数据
• 一切正常，还是没毛病

手动接口检查

• 找到对应接口
• 调用接口，看日志
• 数据库检查数据
• 一切正常，依然是一点毛病都没有

生产环境再查

页面操作 - 整个对象修改

• 页面修改数据
• 检查前端入参
• 看接口日志
• 数据库检查数据
• 问题重现!!!

页面操作 - 单个字段修改

在页面上，任务的开关有个快捷修改入口，直接放在列表

测试一下，发现页面展示表和 celery 表字段都被正常修改
内心 os: 这会是一个突破口吗？
检查前端传参：

• 修改任务开关，只是传了一个参数
• 编辑任务，传整个对象

手动检查接口，字段差异对比

• 模拟修改任务开关请求，只传开关一个字段，结果符合预期
• 开关字段 + 其他字段a，还是老问题，页面展示表字段被修改，celery字段没被修改
• 难道是是字段a的问题?
• 开关字段 + 其他字段b，跟字段a一样，看来并不是字段a的问题，真是令人头大

原因猜想

数据差异?

这时不禁问，难道是生产环境和本地，测试环境的数据差异？
那试一下呗，正好本地和测试都有那批数据
本地和测试都再来一遍上面的检查步骤，问题还是没有复现

特殊数据？

难道是生产环境个别特殊数据才会这样?
换个数据试一下，问题还是必现！
那看来并不是特殊数据的问题？

群里面问问?

遇事不决，加日志

这似乎也看不出来什么问题啊，怎么办？
看来加日志也是很需要讲究的
但是这时候已经快下班了，明天再搞吧

高铁上的探索

真的能放下不管，明天再搞？
作为一名有强迫症的程序员，那是肯定放不下的
在深圳回来广州的高铁上，还是忍不住继续去思考
虽然高铁上，iPhone 的信号很差，可是依然是无法阻止我探索的欲望
于是，查到了这篇文章Learn the subtle differences between Save and Update in Django

恍然大悟，我代码save()方法是没有指定更新字段的，后面更新的记录，会覆盖掉前面更新的字段。
不对，不对，不对。为啥在本地和测试环境并没有这个问题，在生产环境却有。

验证update_fields

被这个bug困扰了一个晚上，睡眠并不是很好
一早醒来，迫不及待的去验证save()方法增加update_fields参数的方案
哇塞，加上update_fields之后，还真的可以！页面显示表和celery表的数据都完美更新了
那就直接修改完，提交代码，叫leader合并，搞定！
这显然是不行，即使结果是对的，但依然没有解释清楚，为啥本地和测试环境没问题，但生产环境就有问题！

数据库主从模式的坑

既然本地，测试，生产环境代码都是一样，那有啥是不一样的。
没错，那就是数据库配置了。生产环境数据库为了高可用，是主从模式，而测试和本地都是单机模式。
说是这么说，那怎么验证呢？
毫无疑问，还是得加日志。
那加在哪里，这个很关键
突然想起了群里面ayo同学的一句话，在此非常感谢ayo同学

加了68行的日志

本地日志

本地68,71,59行可以看出来
更新前crontab_id=395，新crontab_id是399
在更新status时，获取到crontab_id值也是399，符合预期
生产日志

生产68,71,59行可以看出来
更新前crontab_id=399，新crontab_id是1107
在更新status时，但获取到crontab_id却是旧值399，不符合预期
至此，就可以解释清楚，为啥本地和测试环境没问题，但生产环境就有问题
因为本地和测试环境更新crontab是写入的是主库
在更新status时，读取的也是主库。始终都是在一个数据库上操作
生产环境更新crontab，写入的是主库
更新status时，读取却是走了从库。
数据库主从同步是有延迟的，肯定没有代码执行的快，所以从库的数据就还是旧数据
在没有指定update_fields时，更新的是所有字段，最终导致，crontab_id就被旧值覆盖了。
最终的效果就是页面展示表数据是正常更新的，但celery表看起来没有被更新一样，实际是被旧值覆盖

解决

• 读取时数据库，指定走主库
• 更新字段时，使用update_fields指定只更新需要的字段

总结

• 性能不敏感时，可以增加更多的日志，尤其是更新数据时，可以打印出更新前后的数据，方便后续排查
• Django save()方法一定要小心，可能出现旧数据覆盖问题，可考虑使用update方法代替
• 数据库是主从模式，且从库是只读时；在更新数据时，必须指定走主库，从库延迟会导致读取到旧数据

原文
我在【TesterHome 系列征文活动 | 有意思的 bug】https://testerhome.com/topics/33905 等你，一起 day day up！