[BUG] 在计划任务的执行过程中，系统时间的变化可能导致执行时间不正确

gowy222 commented 1 year ago

联系方式

No response

1Panel 版本

1.7.4

问题描述

2022/12/22 19:56:14 1420 :233 (断电开机时间错乱？) [2022-12-22 19:56:14] [ERROR] App Store synchronization failed
[2023-10-31 14:14:58] [INFO] AppStore scheduled task in progress ...
[2023-10-31 14:14:58] [INFO] Starting synchronization with App Store...
[2023-10-31 14:14:58] [INFO] The scheduled certificate update task is currently in progress ...
[2023-10-31 14:14:58] [INFO] The scheduled certificate update task has completed
[2023-10-31 14:14:58] [INFO] Website scheduled task in progress ...
[2023-10-31 14:14:58] [INFO] Website scheduled task has completed
[2023-10-31 14:15:02] [INFO] start to handle remove expired, retain copies: 7
panic: runtime error: invalid memory address or nil pointer dereference [signal SIGSEGV: segmentation violation code=0x1 addr=0x20 pc=0x52d6c0]

goroutine 114 [running]: github.com/gin-gonic/gin.(Context).requestHeader(...) github.com/gin-gonic/gin@v1.9.1/context.go:833 github.com/gin-gonic/gin.(Context).GetHeader(...) github.com/gin-gonic/gin@v1.9.1/context.go:871 github.com/1Panel-dev/1Panel/backend/i18n.GinI18nLocalize.func1(0x7f02f902f9?, {0x205e8dd, 0x2}) github.com/1Panel-dev/1Panel/backend/i18n/i18n.go:71 +0x20 github.com/gin-contrib/i18n.(ginI18nImpl).getMessage(0x4001962840, {0x1a0e480, 0x40008ee140}) github.com/gin-contrib/i18n@v0.0.1/ginI18n.go:26 +0x64 github.com/gin-contrib/i18n.(ginI18nImpl).mustGetMessage(0x0?, {0x1a0e480?, 0x40008ee140?}) github.com/gin-contrib/i18n@v0.0.1/ginI18n.go:44 +0x24 github.com/gin-contrib/i18n.MustGetMessage(...) github.com/gin-contrib/i18n@v0.0.1/i18n.go:67 github.com/1Panel-dev/1Panel/backend/i18n.GetErrMsg({0x1f3fca0, 0x10}, 0x400196e840) github.com/1Panel-dev/1Panel/backend/i18n/i18n.go:41 +0xb8 github.com/1Panel-dev/1Panel/backend/buserr.BusinessError.Error({{0x1f3fca0, 0x10}, {0x0, 0x0}, 0x400196e840, {0x3e449c0, 0x400196e810}}) github.com/1Panel-dev/1Panel/backend/buserr/errors.go:20 +0x50 github.com/1Panel-dev/1Panel/backend/cron/job.(app).Run(0x400006b770?) github.com/1Panel-dev/1Panel/backend/cron/job/app.go:17 +0x68 github.com/robfig/cron/v3.DelayIfStillRunning.func1.1() github.com/robfig/cron/v3@v3.0.1/chain.go:71 +0x1a8 github.com/robfig/cron/v3.FuncJob.Run(0x0?) github.com/robfig/cron/v3@v3.0.1/cron.go:136 +0x24 github.com/robfig/cron/v3.(Cron).startJob.func1() github.com/robfig/cron/v3@v3.0.1/cron.go:312 +0x60 created by github.com/robfig/cron/v3.(*Cron).startJob github.com/robfig/cron/v3@v3.0.1/cron.go:310 +0xa8 [2023-10-31 14:15:09] [INFO] init logger successfully
[2023-10-31 14:15:09] [INFO] init db successfully
[2023-10-31 14:15:09] [INFO] Migration run successfully
[2023-10-31 14:15:09] [INFO] init cache successfully
[2023-10-31 14:15:09] [INFO] init session successfully
[2023-10-31 14:15:12] [INFO] add ntp job time successful
[2023-10-31 14:15:12] [INFO] start cronjob entryID: 5
[2023-10-31 14:15:12] [INFO] add shell job 重启docker_中午11点 successful
[2023-10-31 14:15:12] [INFO] start cronjob entryID: 6
[2023-10-31 14:15:12] [INFO] add shell job 重启frpc successful
[2023-10-31 14:15:12] [INFO] start cronjob entryID: 7
[2023-10-31 14:15:12] [INFO] add shell job 重启docker_晚上8点 successful
[2023-10-31 14:15:12] [INFO] start cronjob entryID: 8
[2023-10-31 14:15:12] [INFO] Starting synchronization with App Store...
[2023-10-31 14:15:12] [INFO] server run success on 233 with http

每一个重启docke任务都是分开定时的，不能同时运行，会相互卡bug(同样的docker命令同时并行)，结果1panel通电开机就全部每个都执行，导致docker完整卡住一个容器都跑不了。。。如果通电开机就一个个启动计划任务，那设置指定时间还有何意义， start cronjob 都没做二次时间验证，都不判断当前系统时间到没到job指定的时间？

重现步骤

断电重启。

同一个 docker-compose -f /XXX.yml down --volumes && docker network prune -f && docker-compose -f /XXX.yml up -d --pull=always && sleep 5 && docker system prune --volumes -f 一个设置中午11点执行，一个设置晚上8点执行，通电开机并行，直接任务都卡住 '一直运行中'，容器一直不上线。

期待的正确结果

通电开机，计划任务不应该就立即不区分该任务设置的时间就运行。 start cronjob 应该引入协程来hook验证当前任务配置的时间到没到。如果start的逻辑有bug，那么这个协程就是一个安全锁。

而且说实话，任何计划任务，都应该在开机 1panel 默认强制获取一次 ntp时间之后，再开启整个进程。当然需要考虑线下服务器断网单独开机无法获取ntp时间同步的情况。尽最大可能先确保服务器时间OK，才能进一步确认计划任务时间对得上。退而求其次，脱机服务器就只能跳过ntp直接开始计划任务总控进程。

ps，有没有一种可能，1panel缓存导致？对于线下脱机服务器，想用1panel，能不能提供无缓存模式启动1panel？开机跳过缓存我觉得更合理。这几秒消耗初始化还是值得的。

附加信息

No response

ssongliu commented 1 year ago

感谢反馈，目前的计划任务不是通过 Linux 服务器的 crontab 来实现的，服务关闭后会停止，重启后，需要拉起数据库中的计划任务。

这里日志并不是去执行对应的任务，而是拉起过程中打的日志，具体执行时间可以看计划任务列表中的上次执行时间。

gowy222 commented 1 year ago

感谢反馈，目前的计划任务不是通过 Linux 服务器的 crontab 来实现的，服务关闭后会停止，重启后，需要拉起数据库中的计划任务。

这里日志并不是去执行对应的任务，而是拉起过程中打的日志，具体执行时间可以看计划任务列表中的上次执行时间。

为何要关闭此问题？这的确是个bug，确实时开机立即执行了计划任务，时间却没到。早上8点多开机为何会执行11点半的计划任务？确定不是bug？ @wanghe-fit2cloud @ssongliu

wanghe-fit2cloud commented 1 year ago

感谢反馈，目前的计划任务不是通过 Linux 服务器的 crontab 来实现的，服务关闭后会停止，重启后，需要拉起数据库中的计划任务。这里日志并不是去执行对应的任务，而是拉起过程中打的日志，具体执行时间可以看计划任务列表中的上次执行时间。

为何要关闭此问题？这的确是个bug，确实时开机立即执行了计划任务，时间却没到。早上8点多开机为何会执行11点半的计划任务？确定不是bug？ @wanghe-fit2cloud @ssongliu

上面已经回复，重启 1Panel 是要拉起定时任务，并不是你所认知的使用 Linux 服务器的 crontab 管理。

具体执行去看计划任务列表中的上次执行时间。

ssongliu commented 1 year ago

这里我们在开发环境测试了 1panel 重启、服务器重启、断电都没有复现这个情况。可以执行一下 1pctl restart 看一下是否会触发计划任务执行。

麻烦提供一下日志审计截图，手动执行会有操作记录如下图：

gowy222 commented 1 year ago

这里我们在开发环境测试了 1panel 重启、服务器重启、断电都没有复现这个情况。可以执行一下 1pctl restart 看一下是否会触发计划任务执行。

麻烦提供一下日志审计截图，手动执行会有操作记录如下图：

2023-11-02 08:24:42 这个开机自动执行的没有任何操作记录。开机1panel日志里面也没有。而且上一天的日期不知为何变成2022年.

gowy222 commented 1 year ago

这里我们在开发环境测试了 1panel 重启、服务器重启、断电都没有复现这个情况。可以执行一下 1pctl restart 看一下是否会触发计划任务执行。

麻烦提供一下日志审计截图，手动执行会有操作记录如下图：

gowy222 commented 1 year ago

这里我们在开发环境测试了 1panel 重启、服务器重启、断电都没有复现这个情况。可以执行一下 1pctl restart 看一下是否会触发计划任务执行。

麻烦提供一下日志审计截图，手动执行会有操作记录如下图：

gowy222 commented 1 year ago

1pctl restart 软重启之后不会触发

gowy222 commented 1 year ago

晚点我试试把1panel装到非overlay系统分区再看看

gowy222 commented 1 year ago

所以，这种情况，1panel这边能不能先尝试修正服务器当前时间，再启动Cronjob实列，再加入job到列队。

gowy222 commented 1 year ago

https://github.com/robfig/cron/blob/bc59245fe10efaed9d51b56900192527ed733435/cron.go#L269

`func (c *Cron) run() { c.logger.Info("start")

// Figure out the next activation times for each entry.
now := c.now()
for _, entry := range c.entries {
    entry.Next = entry.Schedule.Next(now)
    c.logger.Info("schedule", "now", now, "entry", entry.ID, "next", entry.Next)
}

for {
    // Determine the next entry to run.
    sort.Sort(byTime(c.entries))

    var timer *time.Timer
    if len(c.entries) == 0 || c.entries[0].Next.IsZero() {
        // If there are no entries yet, just sleep - it still handles new entries
        // and stop requests.
        timer = time.NewTimer(100000 * time.Hour)
    } else {
        timer = time.NewTimer(c.entries[0].Next.Sub(now))
    }

    for {
        select {
        case now = <-timer.C:
            now = now.In(c.location)
            c.logger.Info("wake", "now", now)

            // Run every entry whose next time was less than now
            for _, e := range c.entries {
                if e.Next.After(now) || e.Next.IsZero() {
                    break
                }
                c.startJob(e.WrappedJob)
                e.Prev = e.Next
                e.Next = e.Schedule.Next(now)
                c.logger.Info("run", "now", now, "entry", e.ID, "next", e.Next)
            }

        case newEntry := <-c.add:
            timer.Stop()
            now = c.now()
            newEntry.Next = newEntry.Schedule.Next(now)
            c.entries = append(c.entries, newEntry)
            c.logger.Info("added", "now", now, "entry", newEntry.ID, "next", newEntry.Next)

        case replyChan := <-c.snapshot:
            replyChan <- c.entrySnapshot()
            continue

        case <-c.stop:
            timer.Stop()
            c.logger.Info("stop")
            return

        case id := <-c.remove:
            timer.Stop()
            now = c.now()
            c.removeEntry(id)
            c.logger.Info("removed", "entry", id)
        }

        break
    }
}

}`

这和第三方模块逻辑有关，核心问题是开机时间错误导致的bug，开发板主板 1panel开机获取默认时间可能是开发板或者固件的一个‘当初’时间开机2022年，

假设: 系统启动时，当前时间为2022年1月1日10:00。对于每一个entry，函数会计算其下一个执行时间。对于我的job，下一个执行时间会被设置为2022年1月1日11:00。

接着，主循环开始，并根据job的下一个执行时间设置一个定时器。定时器的时长是1小时。

1panel后来启动之后，系统时间被修复为2023年11月2日10:05。但此时，定时器仍然在计时，它并不知道时间发生了变化。

没有其他新的entry添加，也没有entry被移除或其他操作，因此我们可以忽略其他的select条件。

当定时器触发时，当前时间已经是2023年11月2日11:00。在for _, e := range c.entries循环中，会检查每个entry的下一个执行时间是否小于或等于当前时间。对于我们每天11的job，它的下一个执行时间（2022年1月1日11:00）确实小于当前时间（2023年11月2日11:00），因此job会被立即执行。

@ssongliu

gowy222 commented 1 year ago

换言之，1panel通过ntp发现系统时间错误的情况下，需要重启整个cronjob实列或者重置计算所有job的下一次启动时间来修正Schedule

ssongliu commented 1 year ago

意思是我现在建一个计划任务，每天 11.30 分执行，默认的下一次执行时间是 11-03 11:30，如果我的系统时间由 11-02 13:43 一下跳到 11-04 08:00，他就会立马执行一次是吧？

gowy222 commented 1 year ago

意思是我现在建一个计划任务，每天 11.30 分执行，默认的下一次执行时间是 11-03 11:30，如果我的系统时间由 11-02 13:43 一下跳到 11-04 08:00，他就会立马执行一次是吧？

是的。 if e.Next.After(now) || e.Next.IsZero() { break } //换言之就是之前计算的下一次启动时间小于等于当前时间就会被执行。now是每次都取新的，随系统时间变化，但是历史计算的下一次启动时间是写死到列队里面的。

ssongliu commented 1 year ago

你是有另外一个计划任务同时去同步时间吗？

我刚开启了一下计划任务设置为每天 11:30 执行，然后上系统直接修改时间到 date -s "2023-11-05 13:51:00"，无论重启系统还是断电都不会触发重新执行。

我也研究一下这个代码。

gowy222 commented 1 year ago

对，确实有

ssongliu commented 1 year ago

仔细读了一下源码，确实在计划任务过程中修改时间可能会导致执行的问题：

源码：先遍历所有的任务，如果没有任务则休眠，有任务则根据下一次执行时间排序，然后加上一个定时器记录最近任务的执行时间点，这时候假如离下次执行时间还有 30 分钟，然后修改了系统时间到早上 8 点，在 8:30 的时候，定时器响起，开始执行任务。 if e.Next.After(now) || e.Next.IsZero() { break } 这里只是判断了执行时间和当前时间的先后，没有比较时间点是否满足时间格式，问题出在这，从 1panel 这边去控制不是很好操作，我看看能不能给他们提一个 issue。

暂时解决办法：将时间同步的计划任务修改一下执行周期。

gowy222 commented 1 year ago

临时解决方案2?

https://github.com/1Panel-dev/1Panel/blob/dev/backend/cron/cron.go#L45 1panel这边能不能在整个函数 func Run 第一步先强制尝试走网络ntp获取一次时间？再 global.Cron.Start()，至少给一次上层级提前纠正系统时间的机会 (脱机服务器就没办法了..) @ssongliu

ssongliu commented 1 year ago

临时解决方案2?

https://github.com/1Panel-dev/1Panel/blob/dev/backend/cron/cron.go#L45 1panel这边能不能在整个函数 func Run 第一步先强制尝试走网络ntp获取一次时间？再 global.Cron.Start()，至少给一次上层级提前纠正系统时间的机会 (脱机服务器就没办法了..) @ssongliu

没问题，这样也是可以的，1.8 版本在服务器启动时，先尝试同步系统时间。

wanghe-fit2cloud commented 1 year ago

v1.8.0 版本已发布。

gowy222 commented 1 year ago

@wanghe-fit2cloud @ssongliu 老哥，还是不行。看看能不能还能咋优化一下，或者改一下机制。

昨晚(9号)更新的1.8

1.开机的时间2022年，首次获取ntp修复时间失败，(通电开机但是路由器可能拨号还没完成，网还没通...) 2.[2022-12-22 19:55:55] [ERROR] App Store synchronization failed 这一条之后系统时间被修复过来了... 换言之，路由器拨号通了.. 可是，这里没看到ntp请求..系统时间怎么恢复的？ 3.ntp节点问题，有时候阿里云节点确实抽风，所以 ntp服务器能不能配置多个地址，按顺序尝试？比如配置3个地址，每个都尝试一次？建议: 加入 # 腾讯云 NTP 服务概述内网 NTP 服务器 time1.tencentyun.com time2.tencentyun.com time3.tencentyun.com time4.tencentyun.com time5.tencentyun.com

外网 NTP 服务器 ntp.tencent.com ntp1.tencent.com ntp2.tencent.com ntp3.tencent.com ntp4.tencent.com ntp5.tencent.com

最后还是回到老问题，系统时间通电开机错误，但是每次面板彻底启动时间又能修复过来。有点不解，到底还有哪些地方自动调用了修复时间？计划任务的逻辑，能不能整体往后挪？

gowy222 commented 1 year ago

其实也就是开机(或者1panel启动)那10秒左右的时间..发生的.. 要不，给个总配置选项...1panel启动直接 sleep多少秒..? 让拨号的去拨号，让Linux系统底层该干嘛的先去干嘛...

gowy222 commented 1 year ago

不过也吐槽一下这个第三方cronjob模块，即使开机2022年，但是也没到2022年的中午11:30，还是被立即执行了job。根本问题还是期望这个第三方模块尽快修复。

https://github.com/robfig/cron 这个模块最后一次更新是2020年? issues里面同类问题挺多... 要不咱换个第三方cron模块吧..

ssongliu commented 11 months ago

@wanghe-fit2cloud @ssongliu 老哥，还是不行。看看能不能还能咋优化一下，或者改一下机制。

昨晚(9号)更新的1.8

1.开机的时间2022年，首次获取ntp修复时间失败，(通电开机但是路由器可能拨号还没完成，网还没通...) 2.[2022-12-22 19:55:55] [ERROR] App Store synchronization failed 这一条之后系统时间被修复过来了... 换言之，路由器拨号通了.. 可是，这里没看到ntp请求..系统时间怎么恢复的？ 3.ntp节点问题，有时候阿里云节点确实抽风，所以 ntp服务器能不能配置多个地址，按顺序尝试？比如配置3个地址，每个都尝试一次？建议: 加入 # 腾讯云 NTP 服务概述内网 NTP 服务器 time1.tencentyun.com time2.tencentyun.com time3.tencentyun.com time4.tencentyun.com time5.tencentyun.com

外网 NTP 服务器 ntp.tencent.com ntp1.tencent.com ntp2.tencent.com ntp3.tencent.com ntp4.tencent.com ntp5.tencent.com

最后还是回到老问题，系统时间通电开机错误，但是每次面板彻底启动时间又能修复过来。有点不解，到底还有哪些地方自动调用了修复时间？计划任务的逻辑，能不能整体往后挪？

你这里时间同步超时了，可以在面板设置里面修改同步 ntp 服务器。

1Panel-dev / 1Panel