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 3f67a0bd9f2198df8ea92f43a0ec09a569378b44..fb7f5c4dd983dc71be428204f5ecec94ba4c78e5 100644 (file)
--- 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 f3dcfe247d720b08d6d60f9b2ea27fe15c52905f..9b95ce7a5722319630fa8bcf27fb0e8f8fc16511 100644 (file)
--- 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 fbaebe4be7076ff70eb6db002eb22f65c54f22ec..ea02ed6a0624f3fada5dc834c9462fc36ae937a5 100644 (file)
--- 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 f83c2e44d7004ab12c036dc6caa6c993122cecc2..85e11d09c12d0ca7786ab0d55b39b3b45485290d 100644 (file)
--- 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