From 2ac49a95206f068b7afe8f3490f3db4be4f999ac Mon Sep 17 00:00:00 2001 From: Pierre de La Morinerie Date: Sun, 8 May 2022 13:28:13 +0000 Subject: [PATCH 1/2] server: warn on missed ticks On heavy load, or when upgrading the server, the plugin might not tick every seconds. To better quantify this, log when some ticks are missed. --- server/reminder.go | 49 +++++++++++++++++++++++++++++++++++- server/reminder_test.go | 55 ++++++++++++++++++++++++++++++++++++----- 2 files changed, 97 insertions(+), 7 deletions(-) diff --git a/server/reminder.go b/server/reminder.go index 2ea8226..fd6b8bb 100755 --- a/server/reminder.go +++ b/server/reminder.go @@ -39,9 +39,31 @@ type ReminderRequest struct { } func (p *Plugin) TriggerReminders() { + tickAt := time.Now().UTC().Round(time.Second) + //p.API.LogInfo("TickAt: " + fmt.Sprintf("%v", tickAt)) - bytes, err := p.API.KVGet(string(fmt.Sprintf("%v", time.Now().UTC().Round(time.Second)))) + // Read the LastTickAt time + lastTickAt := p.getLastTickTimeWithDefault(tickAt) + //p.API.LogInfo("lastTickAt: " + fmt.Sprintf("%v", lastTickAt)) + // Before handling more operations, save the updated LastTickAt time + p.setLastTickTime(tickAt) + + // Detect missed ticks + tickDelta := tickAt.Sub(lastTickAt) + if tickDelta.Seconds() > 1 { + p.API.LogInfo(fmt.Sprintf("Missed %v reminder tick(s)", tickDelta.Seconds() - 1)) + } + + // Trigger the actual tick + p.TriggerRemindersForTick(tickAt) +} + +func (p *Plugin) TriggerRemindersForTick(tickAt time.Time) { + p.API.LogDebug("Trigger reminders at " + fmt.Sprintf("%v", tickAt)) + + // Look up reminders to be triggered for the tick time + bytes, err := p.API.KVGet(string(fmt.Sprintf("%v", tickAt))) if err != nil { p.API.LogError("failed KVGet %s", err) } @@ -583,3 +605,28 @@ func (p *Plugin) findReminder(reminders []Reminder, occurrence Occurrence) Remin } return Reminder{} } + +func (p *Plugin) getLastTickTimeWithDefault(defaultValue time.Time) time.Time { + bytes, err := p.API.KVGet("LastTickAt") + if err != nil { + p.API.LogInfo(fmt.Sprintf("Failed to read LastTickAt (%v); returning the default value", err)) + return defaultValue + } + if bytes == nil { + p.API.LogDebug("LastTickAt is not set; returning the default value") + return defaultValue + } + + lastTickAt, parseErr := time.Parse(time.RFC3339, string(bytes[:])) + if parseErr != nil { + p.API.LogInfo(fmt.Sprintf("Failed to parse LastTickAt value (%v); returning the default value", parseErr)) + return defaultValue + } + + return lastTickAt +} + +func (p *Plugin) setLastTickTime(lastTickAt time.Time) { + serializedTime := lastTickAt.Format(time.RFC3339) + p.API.KVSet("LastTickAt", []byte(serializedTime)) +} diff --git a/server/reminder_test.go b/server/reminder_test.go index 7117aef..d63d609 100755 --- a/server/reminder_test.go +++ b/server/reminder_test.go @@ -14,6 +14,48 @@ import ( ) func TestTriggerReminders(t *testing.T) { + testTime := time.Now().UTC().Round(time.Second) + serializedTestTime := []byte(testTime.Format(time.RFC3339)) + + t.Run("it triggers reminders scheduled for the current time", func(t *testing.T) { + oneSecondAgo, _ := time.ParseDuration("-1s") + lastTickAt := testTime.Add(oneSecondAgo) + serializedLastTickAt := []byte(lastTickAt.Format(time.RFC3339)) + + api := &plugintest.API{} + api.On("KVGet", string("LastTickAt")).Return(serializedLastTickAt, nil) + api.On("KVSet", string("LastTickAt"), serializedTestTime).Return(nil) + api.On("LogDebug", "Trigger reminders at " + fmt.Sprintf("%v", testTime)) + api.On("KVGet", string(fmt.Sprintf("%v", testTime))).Return(nil, nil) + defer api.AssertExpectations(t) + + p := &Plugin{} + p.API = api + + p.TriggerReminders() + }) + + t.Run("when ticks have been missed, it logs a statement", func(t *testing.T) { + threeSecondsAgo, _ := time.ParseDuration("-3s") + lastTickAt := testTime.Add(threeSecondsAgo) + serializedLastTickAt := []byte(lastTickAt.Format(time.RFC3339)) + + api := &plugintest.API{} + api.On("KVGet", string("LastTickAt")).Return(serializedLastTickAt, nil) + api.On("KVSet", string("LastTickAt"), serializedTestTime).Return(nil) + api.On("LogInfo", "Missed 2 reminder tick(s)") + api.On("LogDebug", "Trigger reminders at " + fmt.Sprintf("%v", testTime)) + api.On("KVGet", string(fmt.Sprintf("%v", testTime))).Return(nil, nil) + defer api.AssertExpectations(t) + + p := &Plugin{} + p.API = api + + p.TriggerReminders() + }) +} + +func TestTriggerRemindersForTick(t *testing.T) { user := &model.User{ Email: "-@-.-", @@ -82,13 +124,14 @@ func TestTriggerReminders(t *testing.T) { stringOccurrences, _ := json.Marshal(occurrences) api := &plugintest.API{} + api.On("LogDebug", mock.Anything, mock.Anything, mock.Anything).Maybe() api.On("KVGet", string(fmt.Sprintf("%v", testTime))).Return(stringOccurrences, nil) defer api.AssertExpectations(t) p := &Plugin{} p.API = api - p.TriggerReminders() + p.TriggerRemindersForTick(testTime) }) @@ -102,7 +145,7 @@ func TestTriggerReminders(t *testing.T) { p := &Plugin{} p.API = api - p.TriggerReminders() + p.TriggerRemindersForTick(testTime) }) @@ -117,7 +160,7 @@ func TestTriggerReminders(t *testing.T) { p := &Plugin{} p.API = api - p.TriggerReminders() + p.TriggerRemindersForTick(testTime) }) @@ -132,7 +175,7 @@ func TestTriggerReminders(t *testing.T) { p := &Plugin{} p.API = api - p.TriggerReminders() + p.TriggerRemindersForTick(testTime) }) @@ -178,7 +221,7 @@ func TestTriggerReminders(t *testing.T) { p := &Plugin{} p.API = api - p.TriggerReminders() + p.TriggerRemindersForTick(testTime) }) @@ -222,7 +265,7 @@ func TestTriggerReminders(t *testing.T) { p := &Plugin{} p.API = api - p.TriggerReminders() + p.TriggerRemindersForTick(testTime) }) From 3d53fcfa78fb949b5e89327ec98d05d2a9b92c5e Mon Sep 17 00:00:00 2001 From: Pierre de La Morinerie Date: Mon, 9 May 2022 12:28:04 +0000 Subject: [PATCH 2/2] server: catch up on missed ticks Catches up ticks up to 10 minutes (as longer may overload the server when starting up after being stopped a very long time). If it takes longer to catch up for ticks that a tick, the missed ticks will be caught up on the next turn. --- server/reminder.go | 27 +++++++++++++++++++-------- server/reminder_test.go | 15 +++++++++++---- 2 files changed, 30 insertions(+), 12 deletions(-) diff --git a/server/reminder.go b/server/reminder.go index fd6b8bb..d7f6875 100755 --- a/server/reminder.go +++ b/server/reminder.go @@ -40,19 +40,30 @@ type ReminderRequest struct { func (p *Plugin) TriggerReminders() { tickAt := time.Now().UTC().Round(time.Second) - //p.API.LogInfo("TickAt: " + fmt.Sprintf("%v", tickAt)) - - // Read the LastTickAt time lastTickAt := p.getLastTickTimeWithDefault(tickAt) - //p.API.LogInfo("lastTickAt: " + fmt.Sprintf("%v", lastTickAt)) // Before handling more operations, save the updated LastTickAt time p.setLastTickTime(tickAt) - // Detect missed ticks + // Catch up on missed ticks (if any) tickDelta := tickAt.Sub(lastTickAt) - if tickDelta.Seconds() > 1 { - p.API.LogInfo(fmt.Sprintf("Missed %v reminder tick(s)", tickDelta.Seconds() - 1)) + ticksMissed := tickDelta.Seconds() - 1 + if ticksMissed > 0 { + oneSecond := time.Second + maxCatchupDuration, _ := time.ParseDuration("-10m") + catchupStart := lastTickAt.Add(oneSecond) + earliestCatchupStart := tickAt.Add(maxCatchupDuration) + + if (catchupStart.Before(earliestCatchupStart)) { + catchupStart = earliestCatchupStart + p.API.LogInfo(fmt.Sprintf("Too many reminder ticks were missed: occurrences between %v and %v will be dropped.", lastTickAt, catchupStart)) + } + + p.API.LogDebug(fmt.Sprintf("Catching up on %v reminder tick(s)...", tickAt.Sub(catchupStart).Seconds())) + for tick := catchupStart; tick.Before(tickAt); tick = tick.Add(oneSecond) { + p.TriggerRemindersForTick(tick) + } + p.API.LogDebug("Caught up on missed reminder ticks.") } // Trigger the actual tick @@ -60,7 +71,7 @@ func (p *Plugin) TriggerReminders() { } func (p *Plugin) TriggerRemindersForTick(tickAt time.Time) { - p.API.LogDebug("Trigger reminders at " + fmt.Sprintf("%v", tickAt)) + p.API.LogDebug("Trigger reminders for " + fmt.Sprintf("%v", tickAt)) // Look up reminders to be triggered for the tick time bytes, err := p.API.KVGet(string(fmt.Sprintf("%v", tickAt))) diff --git a/server/reminder_test.go b/server/reminder_test.go index d63d609..2245f1a 100755 --- a/server/reminder_test.go +++ b/server/reminder_test.go @@ -25,7 +25,7 @@ func TestTriggerReminders(t *testing.T) { api := &plugintest.API{} api.On("KVGet", string("LastTickAt")).Return(serializedLastTickAt, nil) api.On("KVSet", string("LastTickAt"), serializedTestTime).Return(nil) - api.On("LogDebug", "Trigger reminders at " + fmt.Sprintf("%v", testTime)) + api.On("LogDebug", "Trigger reminders for " + fmt.Sprintf("%v", testTime)) api.On("KVGet", string(fmt.Sprintf("%v", testTime))).Return(nil, nil) defer api.AssertExpectations(t) @@ -35,7 +35,9 @@ func TestTriggerReminders(t *testing.T) { p.TriggerReminders() }) - t.Run("when ticks have been missed, it logs a statement", func(t *testing.T) { + t.Run("when ticks have been missed, it triggers reminders for the missed ticks as well", func(t *testing.T) { + oneSecondsAgo, _ := time.ParseDuration("-1s") + twoSecondsAgo, _ := time.ParseDuration("-2s") threeSecondsAgo, _ := time.ParseDuration("-3s") lastTickAt := testTime.Add(threeSecondsAgo) serializedLastTickAt := []byte(lastTickAt.Format(time.RFC3339)) @@ -43,8 +45,13 @@ func TestTriggerReminders(t *testing.T) { api := &plugintest.API{} api.On("KVGet", string("LastTickAt")).Return(serializedLastTickAt, nil) api.On("KVSet", string("LastTickAt"), serializedTestTime).Return(nil) - api.On("LogInfo", "Missed 2 reminder tick(s)") - api.On("LogDebug", "Trigger reminders at " + fmt.Sprintf("%v", testTime)) + api.On("LogDebug", "Catching up on 2 reminder tick(s)...") + api.On("LogDebug", "Trigger reminders for " + fmt.Sprintf("%v", testTime.Add(twoSecondsAgo))) + api.On("KVGet", string(fmt.Sprintf("%v", testTime.Add(twoSecondsAgo)))).Return(nil, nil) + api.On("LogDebug", "Trigger reminders for " + fmt.Sprintf("%v", testTime.Add(oneSecondsAgo))) + api.On("KVGet", string(fmt.Sprintf("%v", testTime.Add(oneSecondsAgo)))).Return(nil, nil) + api.On("LogDebug", "Caught up on missed reminder ticks.") + api.On("LogDebug", "Trigger reminders for " + fmt.Sprintf("%v", testTime)) api.On("KVGet", string(fmt.Sprintf("%v", testTime))).Return(nil, nil) defer api.AssertExpectations(t)