From: Anderson A. Giacomolli Date: Mon, 9 Nov 2026 13:31:00 +0000 (-0300) Subject: Log each schedule run by its ID X-Git-Url: https://git.giacomolli.uk/onechat/commitdiff_plain/150d707b16a5495272dfb02d690d99bfae50c14e?hp=5b778ad04422dd456b7d673fb653f0353c47b0fe Log each schedule run by its ID Each run of a schedule logs one line with the ID of the schedule, after its message is durable in the chat. A late run after a stop of the daemon tells how late it is. The line holds no text of the schedule, so the log shows that a task ran but not what it asks. Issue: e4acfcb --- diff --git a/daemon.go b/daemon.go index 3f67a0b..fb7f5c4 100644 --- a/daemon.go +++ b/daemon.go @@ -95,7 +95,7 @@ func daemon(ctx context.Context, out io.Writer) (err error) { err = errors.Join(err, memory.Close()) }() - schedules, err := openSchedules(filepath.Join(agent.dir, scheduleFileName), time.Now) + schedules, err := openSchedules(filepath.Join(agent.dir, scheduleFileName), time.Now, logger) if err != nil { return err } diff --git a/schedule.go b/schedule.go index f3dcfe2..9b95ce7 100644 --- a/schedule.go +++ b/schedule.go @@ -6,6 +6,7 @@ import ( "encoding/json" "errors" "fmt" + "log" "os" "slices" "strconv" @@ -48,11 +49,13 @@ const ( ) // openSchedules reads the schedules of the file at path. A missing file holds -// none. The clock gives the time and the time zone of the schedules. -func openSchedules(path string, clock func() time.Time) (*Schedules, error) { +// none. The clock gives the time and the time zone of the schedules, and logger +// gets one line for each run. +func openSchedules(path string, clock func() time.Time, logger *log.Logger) (*Schedules, error) { s := &Schedules{ path: path, clock: clock, + logger: logger, check: scheduleCheck, changed: make(chan struct{}, 1), } @@ -93,6 +96,7 @@ func openSchedules(path string, clock func() time.Time) (*Schedules, error) { type Schedules struct { path string clock func() time.Time + logger *log.Logger check time.Duration changed chan struct{} @@ -244,7 +248,9 @@ func (s *Schedules) Remove(id int) (string, error) { // deliver logs the message of each due schedule in l, in due order, as a work // message of scheduleSource, and wakes the loop once with all of them. A // schedule ends its run with Done after its message is durable in the log. A -// crash between the two makes the run repeat once. +// crash between the two makes the run repeat once. Each run logs one line with +// the ID of the schedule and, for a late run, how late it is. The line holds no +// text of the schedule. func (s *Schedules) deliver(ctx context.Context, l *TurnLoop) error { now := s.clock() var turns []Message @@ -270,6 +276,12 @@ func (s *Schedules) deliver(ctx context.Context, l *TurnLoop) error { return err } + if schedule.late(now) { + s.logger.Printf("schedule %d runs %s late, because the daemon was stopped at its time", schedule.ID, durationText(now.Sub(schedule.Due))) + } else { + s.logger.Printf("schedule %d runs", schedule.ID) + } + turns = append(turns, message) } @@ -402,13 +414,19 @@ func (s Schedule) Message(now time.Time) string { s.Text, } - if now.Sub(s.Due) > scheduleLate { + if s.late(now) { lines = append(lines, scheduleLateLine) } return strings.Join(append(lines, scheduleEmptyReply), "\n") } +// late tells if a run at now is late: more than scheduleLate after the due +// time. +func (s Schedule) late(now time.Time) bool { + return now.Sub(s.Due) > scheduleLate +} + // repeats returns once for a one-time schedule, or else repeats and the cron // expression. func (s Schedule) repeats() string { diff --git a/schedule_helper_test.go b/schedule_helper_test.go index fbaebe4..ea02ed6 100644 --- a/schedule_helper_test.go +++ b/schedule_helper_test.go @@ -1,6 +1,8 @@ package main import ( + "io" + "log" "path/filepath" "testing" "time" @@ -12,7 +14,7 @@ import ( func newTestSchedules(t *testing.T, clock func() time.Time) *Schedules { t.Helper() - schedules, err := openSchedules(filepath.Join(t.TempDir(), scheduleFileName), clock) + schedules, err := openSchedules(filepath.Join(t.TempDir(), scheduleFileName), clock, log.New(io.Discard, "", 0)) require.NoError(t, err) return schedules diff --git a/schedule_test.go b/schedule_test.go index f83c2e4..85e11d0 100644 --- a/schedule_test.go +++ b/schedule_test.go @@ -2,6 +2,8 @@ package main import ( "context" + "io" + "log" "os" "path/filepath" "strings" @@ -128,7 +130,7 @@ func TestSchedulesSurviveARestart(t *testing.T) { require.NoError(t, err) require.Equal(t, os.FileMode(0o600), info.Mode().Perm()) - reopened, err := openSchedules(path, schedules.clock) + reopened, err := openSchedules(path, schedules.clock, log.New(io.Discard, "", 0)) require.NoError(t, err) require.Equal(t, "2 | Monday 2026-11-09 08:00 -03:00 | 0 8 * * 1-5 | Tell the user the news.", reopened.List()) @@ -230,7 +232,7 @@ func TestOpenSchedulesRefusesABadCron(t *testing.T) { path := filepath.Join(t.TempDir(), scheduleFileName) require.NoError(t, os.WriteFile(path, []byte(`{"next":1,"schedules":[{"id":1,"text":"x","cron":"* * * * *","due":"2026-11-09T09:00:00-03:00"}]}`), 0o600)) - _, err := openSchedules(path, time.Now) + _, err := openSchedules(path, time.Now, log.New(io.Discard, "", 0)) require.ErrorContains(t, err, "schedule 1: the runs of") } @@ -239,7 +241,8 @@ func TestSchedulesRunStartsATurnWhenDue(t *testing.T) { now: time.Date(2026, time.November, 8, 20, 0, 0, 0, time.FixedZone("", -3*60*60)), } - schedules, err := openSchedules(filepath.Join(t.TempDir(), scheduleFileName), clock.Now) + logs := &SyncBuffer{} + schedules, err := openSchedules(filepath.Join(t.TempDir(), scheduleFileName), clock.Now, log.New(logs, "", 0)) require.NoError(t, err) server := newModelFake(t) @@ -256,6 +259,7 @@ func TestSchedulesRunStartsATurnWhenDue(t *testing.T) { require.Equal(t, "[Schedule 1] Sunday 2026-11-08 20:05 -03:00, once\nRemind the user to drink water.\n"+scheduleEmptyReply, texts[len(texts)-1]) require.Equal(t, scheduleSource, test.events.LastEvent("work").Source) require.Equal(t, "No schedules.", schedules.List()) + require.Equal(t, "schedule 1 runs\n", logs.String()) } func TestSchedulesRunMissedSchedulesOnceAtTheStart(t *testing.T) { @@ -266,7 +270,8 @@ func TestSchedulesRunMissedSchedulesOnceAtTheStart(t *testing.T) { now: time.Date(2026, time.November, 8, 20, 30, 0, 0, time.FixedZone("", -3*60*60)), } - schedules, err := openSchedules(path, clock.Now) + logs := &SyncBuffer{} + schedules, err := openSchedules(path, clock.Now, log.New(logs, "", 0)) require.NoError(t, err) server := newModelFake(t) @@ -280,6 +285,7 @@ func TestSchedulesRunMissedSchedulesOnceAtTheStart(t *testing.T) { "[Schedule 2] Sunday 2026-11-08 10:00 -03:00, repeats 0 * * * *\nTell the user the time.\n" + scheduleLateLine + "\n" + scheduleEmptyReply, }, texts[len(texts)-2:]) require.Equal(t, "2 | Sunday 2026-11-08 21:00 -03:00 | 0 * * * * | Tell the user the time.", schedules.List()) + require.Equal(t, "schedule 1 runs 11h30m0s late, because the daemon was stopped at its time\nschedule 2 runs 10h30m0s late, because the daemon was stopped at its time\n", logs.String()) } func TestDaemonRunsADueSchedule(t *testing.T) { @@ -287,7 +293,7 @@ func TestDaemonRunsADueSchedule(t *testing.T) { now: time.Date(2026, time.November, 8, 20, 0, 0, 0, time.FixedZone("", -3*60*60)), } - schedules, err := openSchedules(filepath.Join(t.TempDir(), scheduleFileName), clock.Now) + schedules, err := openSchedules(filepath.Join(t.TempDir(), scheduleFileName), clock.Now, log.New(io.Discard, "", 0)) require.NoError(t, err) schedules.check = time.Millisecond @@ -354,7 +360,7 @@ func scheduleTestOpen(t *testing.T) (*Schedules, string) { now: time.Date(2026, time.November, 8, 20, 0, 0, 0, time.FixedZone("", -3*60*60)), } - schedules, err := openSchedules(path, clock.Now) + schedules, err := openSchedules(path, clock.Now, log.New(io.Discard, "", 0)) require.NoError(t, err) return schedules, path