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

[gowy222]

联系方式

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

附加信息

No response

[ssongliu]

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

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

[gowy222]

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

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

为何要关闭此问题？这的确是个bug，确实时开机立即执行了计划任务，时间却没到。

早上8点多开机为何会执行11点半的计划任务？
确定不是bug？
@wanghe-fit2cloud
@ssongliu

[wanghe-fit2cloud]

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

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

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

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

[ssongliu]

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

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

[gowy222]

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

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

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

[gowy222]

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

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

[gowy222]

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

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

[gowy222]

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

[gowy222]

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

[gowy222]

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

[gowy222]

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