Log daemon events at their slog levels

Each daemon part gives its event, level, and raw attributes to the
shared handler. Normal events use info, recoverable failures use
warning, and lost data or stopped work uses error. Outages still log
only their start and end, and probe and rebuild runs discard their
summary log output.

diff --git a/daemon.go b/daemon.go
index 5ec220ed6d3f144db0805b2f3beb8a06da22ac96..ef738965898575d8b55b9113ae02ba8b08bb862d 100644 (file)
--- a/daemon.go
+++ b/daemon.go
@@ -7,7 +7,6 @@ import (
        "errors"
        "fmt"
        "io"
        "errors"
        "fmt"
        "io"

-       "log"

        "net"
        "os"
        "path/filepath"
        "net"
        "os"
        "path/filepath"


@@ -111,19 +110,19 @@ func daemon(ctx context.Context, out io.Writer) (err error) {
                return err
        }
 
                return err
        }
 

-       linked := "WhatsApp not linked"
+       linked := "not linked"

        if whatsapp.isLinked() {
        if whatsapp.isLinked() {

-               linked = "WhatsApp linked"
+               linked = "linked"

        }
 
        }
 

-       logger.Printf("ready: socket %s, model %s (%s), workdir %s, %s, %d schedules", listener.Addr(), agent.config.Model, agent.config.Effort, agent.config.Workdir, linked, schedules.Len())
+       logger.Info("ready", "socket", listener.Addr(), "model", agent.config.Model, "effort", agent.config.Effort, "workdir", agent.config.Workdir, "whatsapp", linked, "schedules", schedules.Len())

 
        var telegram *TelegramBot
 
        if hasBot {
                telegram = newTelegramBot(newTelegramAPI(telegramAPIURL, botSettings.Token), botSettings.Owner, filepath.Join(agent.dir, telegramOffsetFileName), daemonLogger(out, "telegram: "))
 
 
        var telegram *TelegramBot
 
        if hasBot {
                telegram = newTelegramBot(newTelegramAPI(telegramAPIURL, botSettings.Token), botSettings.Owner, filepath.Join(agent.dir, telegramOffsetFileName), daemonLogger(out, "telegram: "))
 

-               logger.Print("Telegram bot started")
+               logger.Info("Telegram bot started")

        }
 
        return daemonServe(ctx, listener, telegram, whatsapp, schedules, func(notify func(Event)) (*TurnLoop, error) {
        }
 
        return daemonServe(ctx, listener, telegram, whatsapp, schedules, func(notify func(Event)) (*TurnLoop, error) {


@@ -443,25 +442,3 @@ func daemonRunRequest(l *TurnLoop, whatsapp *WhatsApp, request SocketRequest, an
                return fmt.Errorf("unknown request %q", request.Type)
        }
 }
                return fmt.Errorf("unknown request %q", request.Type)
        }
 }

-
-// daemonLogger returns the logger of the part of the daemon with prefix, such
-// as "telegram: ", on out. The journal adds the time to each line and sets
-// JOURNAL_STREAM for a service, so then the lines have no time stamp. Otherwise
-// each line has the standard time stamp.
-func daemonLogger(out io.Writer, prefix string) *log.Logger {
-       if os.Getenv("JOURNAL_STREAM") != "" {
-               return log.New(out, prefix, 0)
-       }
-
-       return log.New(out, prefix, log.LstdFlags)
-}
-
-// durationText returns d for a log line: rounded to the second, or to the
-// millisecond when it is shorter than a second.
-func durationText(d time.Duration) string {
-       if d < time.Second {
-               return d.Round(time.Millisecond).String()
-       }
-
-       return d.Round(time.Second).String()
-}

diff --git a/daemon_log.go b/daemon_log.go
index 15426bcafda9319f05a8284d732413df7fb59828..ef1360cc8ba88ac2eae59190e1b5db7b32fbc561 100644 (file)
--- a/daemon_log.go
+++ b/daemon_log.go
@@ -5,10 +5,24 @@ import (
        "fmt"
        "io"
        "log/slog"
        "fmt"
        "io"
        "log/slog"

+       "os"

        "strings"
        "sync"
        "strings"
        "sync"

+       "time"

 )
 
 )
 

+// daemonLogger returns a logger for one daemon part. JOURNAL_STREAM selects
+// syslog priorities without a time stamp. Other output carries the standard
+// time stamp and level.
+func daemonLogger(out io.Writer, prefix string) *slog.Logger {
+       return slog.New(&DaemonLogHandler{
+               out:     out,
+               prefix:  prefix,
+               journal: os.Getenv("JOURNAL_STREAM") != "",
+               mutex:   &sync.Mutex{},
+       })
+}
+

 // DaemonLogHandler writes short event lines with ordered attributes. Copies
 // share the writer lock. The err attribute follows all other attributes as a
 // cause. Journal lines carry a syslog priority instead of a time and level.
 // DaemonLogHandler writes short event lines with ordered attributes. Copies
 // share the writer lock. The err attribute follows all other attributes as a
 // cause. Journal lines carry a syslog priority instead of a time and level.


@@ -141,3 +155,13 @@ func daemonLogAttr(line *strings.Builder, group string, attr slog.Attr, cause *s
                fmt.Fprint(line, attr.Value.Any())
        }
 }
                fmt.Fprint(line, attr.Value.Any())
        }
 }

+
+// durationText returns d for a log line: rounded to the second, or to the
+// millisecond when it is shorter than a second.
+func durationText(d time.Duration) string {
+       if d < time.Second {
+               return d.Round(time.Millisecond).String()
+       }
+
+       return d.Round(time.Second).String()
+}

diff --git a/daemon_log_helper_test.go b/daemon_log_helper_test.go
new file mode 100644 (file)
index 0000000..3eaa5cf
--- /dev/null
+++ b/daemon_log_helper_test.go
@@ -0,0 +1,17 @@
+package main
+
+import (
+       "io"
+       "log/slog"
+       "sync"
+)
+
+// daemonTestLogger writes journal lines without a part prefix, so tests can
+// check the level and event without a clock.
+func daemonTestLogger(out io.Writer) *slog.Logger {
+       return slog.New(&DaemonLogHandler{
+               out:     out,
+               journal: true,
+               mutex:   &sync.Mutex{},
+       })
+}

diff --git a/daemon_test.go b/daemon_test.go
index bfb4efbcc77e2df7b4576d6e7a29f63a14e79ff0..6a4d98c5a040456d0baf8e06fb4307542bcbb56a 100644 (file)
--- a/daemon_test.go
+++ b/daemon_test.go
@@ -109,12 +109,12 @@ func TestDaemonLogHasATimeStampOnlyOutsideTheJournal(t *testing.T) {
                {
                        name:    "the journal adds the time itself",
                        journal: "8:12345",
                {
                        name:    "the journal adds the time itself",
                        journal: "8:12345",

-                       line:    `^onechat: the agent is ready\n$`,
+                       line:    `^<6>onechat: the agent is ready\n$`,

                },
                {
                        name:    "a terminal gets the time in the line",
                        journal: "",
                },
                {
                        name:    "a terminal gets the time in the line",
                        journal: "",

-                       line:    `^onechat: \d{4}/\d\d/\d\d \d\d:\d\d:\d\d the agent is ready\n$`,
+                       line:    `^\d{4}/\d\d/\d\d \d\d:\d\d:\d\d INFO onechat: the agent is ready\n$`,

                },
        }
 
                },
        }
 


@@ -124,7 +124,7 @@ func TestDaemonLogHasATimeStampOnlyOutsideTheJournal(t *testing.T) {
 
                        var out strings.Builder
 
 
                        var out strings.Builder
 

-                       daemonLogger(&out, "onechat: ").Print("the agent is ready")
+                       daemonLogger(&out, "onechat: ").Info("the agent is ready")

                        require.Regexp(t, tc.line, out.String())
                })
        }
                        require.Regexp(t, tc.line, out.String())
                })
        }

diff --git a/discard_log_helper_test.go b/discard_log_helper_test.go
index 9c24880ff1dd4d2ed6315409d51201f4dda47459..ac6fc0ec8437fefcc04486652b301aa239cc34be 100644 (file)
--- a/discard_log_helper_test.go
+++ b/discard_log_helper_test.go
@@ -1,11 +1,10 @@
 package main
 
 import (
 package main
 
 import (

-       "io"
-       "log"
+       "log/slog"

 )
 
 // discardLog returns a logger whose lines a test does not read.
 )
 
 // discardLog returns a logger whose lines a test does not read.

-func discardLog() *log.Logger {
-       return log.New(io.Discard, "", 0)
+func discardLog() *slog.Logger {
+       return slog.New(slog.DiscardHandler)

 }
 }

diff --git a/memory.go b/memory.go
index 7cbcce68c40f4b06382e3c8f3e71dfcbb3388d26..20f46d62ba6d50397cf6a0b7f892f8a59c2cf688 100644 (file)
--- a/memory.go
+++ b/memory.go
@@ -5,7 +5,7 @@ import (
        "encoding/json"
        "errors"
        "fmt"
        "encoding/json"
        "errors"
        "fmt"

-       "log"
+       "log/slog"

        "os"
        "path/filepath"
        "strings"
        "os"
        "path/filepath"
        "strings"


@@ -25,7 +25,7 @@ var (
 // openMemory opens the chat in root and starts the builds that are ready. The
 // clock gives the dates of new messages and the days of new nodes. logger gets
 // one line for each failed build. The builds stop when ctx ends or at Close.
 // openMemory opens the chat in root and starts the builds that are ready. The
 // clock gives the dates of new messages and the days of new nodes. logger gets
 // one line for each failed build. The builds stop when ctx ends or at Close.

-func openMemory(ctx context.Context, root string, clock func() time.Time, summarizer Summarizer, logger *log.Logger) (*Memory, error) {
+func openMemory(ctx context.Context, root string, clock func() time.Time, summarizer Summarizer, logger *slog.Logger) (*Memory, error) {

        log, err := openLog(ctx, root, clock)
        if err != nil {
                return nil, err
        log, err := openLog(ctx, root, clock)
        if err != nil {
                return nil, err


@@ -108,7 +108,7 @@ type Memory struct {
        cview      *View
        queue      *BuildQueue
        summarizer Summarizer
        cview      *View
        queue      *BuildQueue
        summarizer Summarizer

-       logger     *log.Logger
+       logger     *slog.Logger

        ctx        context.Context
        cancel     context.CancelFunc
        workers    sync.WaitGroup
        ctx        context.Context
        cancel     context.CancelFunc
        workers    sync.WaitGroup


@@ -598,7 +598,7 @@ func (m *Memory) run(key NodeKey, task Task) {
 
 // failed logs the failed build of the node key with its cause err.
 func (m *Memory) failed(key NodeKey, err error) {
 
 // failed logs the failed build of the node key with its cause err.
 func (m *Memory) failed(key NodeKey, err error) {

-       m.logger.Printf("summary failed, retry at next message: node (%d, %d): %v", key.level, key.index, err)
+       m.logger.Warn("summary failed", "level", key.level, "index", key.index, "err", err)

 }
 
 // ready tells if both children of the node key are built and the node is not.
 }
 
 // ready tells if both children of the node key are built and the node is not.

diff --git a/memory_test.go b/memory_test.go
index fe050c4f001dce923fefecbd3244387d53d31ce3..202d4da3648b5e30b02de9e6fd3fd43d470c423e 100644 (file)
--- a/memory_test.go
+++ b/memory_test.go
@@ -3,7 +3,6 @@ package main
 import (
        "context"
        "fmt"
 import (
        "context"
        "fmt"

-       "log"

        "maps"
        "os"
        "path/filepath"
        "maps"
        "os"
        "path/filepath"


@@ -184,7 +183,7 @@ func TestMemorySettleFailsWhileABuildFailed(t *testing.T) {
        summarizer.SetFailing(true)
 
        logs := &SyncBuffer{}
        summarizer.SetFailing(true)
 
        logs := &SyncBuffer{}

-       memory, err := openMemory(t.Context(), t.TempDir(), newTestClock().Now, summarizer, log.New(logs, "", 0))
+       memory, err := openMemory(t.Context(), t.TempDir(), newTestClock().Now, summarizer, daemonTestLogger(logs))

        require.NoError(t, err)
 
        defer func() {
        require.NoError(t, err)
 
        defer func() {


@@ -194,7 +193,7 @@ func TestMemorySettleFailsWhileABuildFailed(t *testing.T) {
        _, err = memory.Append("echo", memoryLongText(0))
        require.NoError(t, err)
        require.ErrorIs(t, memory.Settle(t.Context()), errMemoryUnsettled)
        _, err = memory.Append("echo", memoryLongText(0))
        require.NoError(t, err)
        require.ErrorIs(t, memory.Settle(t.Context()), errMemoryUnsettled)

-       require.Equal(t, "summary failed, retry at next message: node (0, 0): fake failure\n", logs.String())
+       require.Equal(t, "<4>summary failed level=0 index=0: fake failure\n", logs.String())

 
        summarizer.SetFailing(false)
 
 
        summarizer.SetFailing(false)
 

diff --git a/probe.go b/probe.go
index d788fa99cfe7d2f95269be231b0815c04c10ff95..3781cd3a21923c1fae91181bb5853d39d5b76973 100644 (file)
--- a/probe.go
+++ b/probe.go
@@ -7,7 +7,7 @@ import (
        "errors"
        "fmt"
        "io"
        "errors"
        "fmt"
        "io"

-       "log"
+       "log/slog"

        "os"
        "path/filepath"
        "strconv"
        "os"
        "path/filepath"
        "strconv"


@@ -109,7 +109,7 @@ func probe(ctx context.Context, args []string, out io.Writer) (err error) {
 
        // The report of the probe counts the failed calls, so the lines of the
        // failed builds are not needed.
 
        // The report of the probe counts the failed calls, so the lines of the
        // failed builds are not needed.

-       memory, err := openMemory(ctx, root, time.Now, summarizer, log.New(io.Discard, "", 0))
+       memory, err := openMemory(ctx, root, time.Now, summarizer, slog.New(slog.DiscardHandler))

        if err != nil {
                return fmt.Errorf("open probe memory: %w", err)
        }
        if err != nil {
                return fmt.Errorf("open probe memory: %w", err)
        }

diff --git a/rebuild.go b/rebuild.go
index 91b5ae516498da3e5b91d2f4aed898c7230a7b02..11c6bfcc536d1fbff9eef1d0d7c9a83412e5410c 100644 (file)
--- a/rebuild.go
+++ b/rebuild.go
@@ -7,7 +7,7 @@ import (
        "fmt"
        "io"
        "io/fs"
        "fmt"
        "io"
        "io/fs"

-       "log"
+       "log/slog"

        "os"
        "path/filepath"
        "slices"
        "os"
        "path/filepath"
        "slices"


@@ -55,7 +55,7 @@ func rebuild(ctx context.Context, agent *Agent, added []DatedMessage, client *Mo
                }
        }()
 
                }
        }()
 

-       memory, err := openMemory(ctx, root, time.Now, summarizer, log.New(io.Discard, "", 0))
+       memory, err := openMemory(ctx, root, time.Now, summarizer, slog.New(slog.DiscardHandler))

        if err != nil {
                return "", fmt.Errorf("open rebuilt memory: %w", err)
        }
        if err != nil {
                return "", fmt.Errorf("open rebuilt memory: %w", err)
        }

diff --git a/schedule.go b/schedule.go
index d2f53e095887749949320f3af79252f556ba3db8..5da024d39b0e4442235b3329695416cb9ac132eb 100644 (file)
--- a/schedule.go
+++ b/schedule.go
@@ -6,7 +6,7 @@ import (
        "encoding/json"
        "errors"
        "fmt"
        "encoding/json"
        "errors"
        "fmt"

-       "log"
+       "log/slog"

        "os"
        "slices"
        "strconv"
        "os"
        "slices"
        "strconv"


@@ -51,7 +51,7 @@ 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, and logger
 // gets one line for each run.
 // 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, and logger
 // gets one line for each run.

-func openSchedules(path string, clock func() time.Time, logger *log.Logger) (*Schedules, error) {
+func openSchedules(path string, clock func() time.Time, logger *slog.Logger) (*Schedules, error) {

        s := &Schedules{
                path:    path,
                clock:   clock,
        s := &Schedules{
                path:    path,
                clock:   clock,


@@ -96,7 +96,7 @@ func openSchedules(path string, clock func() time.Time, logger *log.Logger) (*Sc
 type Schedules struct {
        path    string
        clock   func() time.Time
 type Schedules struct {
        path    string
        clock   func() time.Time

-       logger  *log.Logger
+       logger  *slog.Logger

        check   time.Duration
        changed chan struct{}
 
        check   time.Duration
        changed chan struct{}
 


@@ -281,12 +281,13 @@ func (s *Schedules) deliver(ctx context.Context, l *TurnLoop) error {
                        return err
                }
 
                        return err
                }
 

+               attrs := []any{"id", schedule.ID}

                if schedule.late(now) {
                if schedule.late(now) {

-                       s.logger.Printf("schedule %d ran %s late", schedule.ID, durationText(now.Sub(schedule.Due)))
-               } else {
-                       s.logger.Printf("schedule %d ran", schedule.ID)
+                       attrs = append(attrs, "late", now.Sub(schedule.Due))

                }
 
                }
 

+               s.logger.Info("schedule ran", attrs...)
+

                turns = append(turns, message)
        }
 
                turns = append(turns, message)
        }
 

diff --git a/schedule_test.go b/schedule_test.go
index cb1b06a1ddf6f87eb49d1ee8441c55813eb83cd7..3048d7584d4e8e793d6b178ab4aa476ba05b1172 100644 (file)
--- a/schedule_test.go
+++ b/schedule_test.go
@@ -2,7 +2,6 @@ package main
 
 import (
        "context"
 
 import (
        "context"

-       "log"

        "os"
        "path/filepath"
        "strings"
        "os"
        "path/filepath"
        "strings"


@@ -242,7 +241,7 @@ func TestSchedulesRunStartsATurnWhenDue(t *testing.T) {
        }
 
        logs := &SyncBuffer{}
        }
 
        logs := &SyncBuffer{}

-       schedules, err := openSchedules(filepath.Join(t.TempDir(), scheduleFileName), clock.Now, log.New(logs, "", 0))
+       schedules, err := openSchedules(filepath.Join(t.TempDir(), scheduleFileName), clock.Now, daemonTestLogger(logs))

        require.NoError(t, err)
 
        server := newModelFake(t)
        require.NoError(t, err)
 
        server := newModelFake(t)


@@ -259,7 +258,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] 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 ran\n", logs.String())
+       require.Equal(t, "<6>schedule ran id=1\n", logs.String())

 }
 
 func TestSchedulesRunMissedSchedulesOnceAtTheStart(t *testing.T) {
 }
 
 func TestSchedulesRunMissedSchedulesOnceAtTheStart(t *testing.T) {


@@ -271,7 +270,7 @@ func TestSchedulesRunMissedSchedulesOnceAtTheStart(t *testing.T) {
        }
 
        logs := &SyncBuffer{}
        }
 
        logs := &SyncBuffer{}

-       schedules, err := openSchedules(path, clock.Now, log.New(logs, "", 0))
+       schedules, err := openSchedules(path, clock.Now, daemonTestLogger(logs))

        require.NoError(t, err)
 
        server := newModelFake(t)
        require.NoError(t, err)
 
        server := newModelFake(t)


@@ -285,7 +284,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())
                "[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 ran 11h30m0s late\nschedule 2 ran 10h30m0s late\n", logs.String())
+       require.Equal(t, "<6>schedule ran id=1 late=11h30m0s\n<6>schedule ran id=2 late=10h30m0s\n", logs.String())

 }
 
 func TestDaemonRunsADueSchedule(t *testing.T) {
 }
 
 func TestDaemonRunsADueSchedule(t *testing.T) {

diff --git a/subagent_run.go b/subagent_run.go
index c5e98df7e0f15316f14be60563f0aee4a35d5b60..0780393db3f87c96e5d6aef425535106c102b4f3 100644 (file)
--- a/subagent_run.go
+++ b/subagent_run.go
@@ -5,7 +5,7 @@ import (
        "encoding/json"
        "errors"
        "fmt"
        "encoding/json"
        "errors"
        "fmt"

-       "log"
+       "log/slog"

        "maps"
        "os"
        "path/filepath"
        "maps"
        "os"
        "path/filepath"


@@ -69,7 +69,7 @@ type SubagentRuns struct {
        report    func(name, text, status string)
        note      func(text string) error
        fail      func(err error)
        report    func(name, text, status string)
        note      func(text string) error
        fail      func(err error)

-       logger    *log.Logger
+       logger    *slog.Logger

        notify    func(Event)
 
        mutex   sync.Mutex
        notify    func(Event)
 
        mutex   sync.Mutex


@@ -243,7 +243,7 @@ func (r *SubagentRuns) Resume(ctx context.Context) error {
        for _, name := range names {
                _, err = r.Tell(ctx, name, text)
                if err != nil {
        for _, name := range names {
                _, err = r.Tell(ctx, name, text)
                if err != nil {

-                       r.logger.Printf("subagent %s lost at restart: %v", name, err)
+                       r.logger.Error("subagent lost at restart", "name", name, "err", err)

                        r.report(name, subagentReport(name, []string{"failed: " + err.Error()}), subagentFailed)
                }
        }
                        r.report(name, subagentReport(name, []string{"failed: " + err.Error()}), subagentFailed)
                }
        }


@@ -355,7 +355,7 @@ func (r *SubagentRuns) start(ctx context.Context, run *SubagentRun) error {
        r.mutex.Unlock()
 
        run.started = r.subagents.clock()
        r.mutex.Unlock()
 
        run.started = r.subagents.clock()

-       r.logger.Printf("subagent %s started", run.subagent.name)
+       r.logger.Info("subagent started", "name", run.subagent.name)

        r.notify(Event{
                Kind: "subagent",
                Text: run.subagent.name,
        r.notify(Event{
                Kind: "subagent",
                Text: run.subagent.name,


@@ -470,14 +470,14 @@ func (r *SubagentRuns) run(ctx context.Context, run *SubagentRun) {
                status = subagentStopped
        }
 
                status = subagentStopped
        }
 

-       length := durationText(r.subagents.clock().Sub(run.started))
+       length := r.subagents.clock().Sub(run.started)

        switch status {
        case subagentStopped:
        switch status {
        case subagentStopped:

-               r.logger.Printf("subagent %s stopped after %s", run.subagent.name, length)
+               r.logger.Info("subagent stopped", "name", run.subagent.name, "after", length)

        case subagentFailed:
        case subagentFailed:

-               r.logger.Printf("subagent %s failed after %s: %v", run.subagent.name, length, failure)
+               r.logger.Error("subagent failed", "name", run.subagent.name, "after", length, "err", failure)

        default:
        default:

-               r.logger.Printf("subagent %s done after %s", run.subagent.name, length)
+               r.logger.Info("subagent done", "name", run.subagent.name, "after", length)

        }
 
        r.report(run.subagent.name, subagentReport(run.subagent.name, replies), status)
        }
 
        r.report(run.subagent.name, subagentReport(run.subagent.name, replies), status)

diff --git a/subagent_run_test.go b/subagent_run_test.go
index f637dcfcc9938edc983bfc75d9c1aba41d3948b6..c5ad2995931a147424fc4ea3d86e27db31281530 100644 (file)
--- a/subagent_run_test.go
+++ b/subagent_run_test.go
@@ -3,6 +3,7 @@ package main
 import (
        "context"
        "io"
 import (
        "context"
        "io"

+       "log/slog"

        "net/http"
        "os"
        "path/filepath"
        "net/http"
        "os"
        "path/filepath"


@@ -69,7 +70,7 @@ func TestSpawnRunsASubagentInTheBackground(t *testing.T) {
                Source: name,
                Status: subagentFinished,
        }, test.events.LastEvent("work"))
                Source: name,
                Status: subagentFinished,
        }, test.events.LastEvent("work"))

-       require.Equal(t, "subagent "+name+" started\nsubagent "+name+" done after 0s\n", test.logs.String())
+       require.Equal(t, "<6>subagent started name="+name+"\n<6>subagent done name="+name+" after=0s\n", test.logs.String())

 
        var first, second *ModelFakeCall
 
 
        var first, second *ModelFakeCall
 


@@ -197,7 +198,7 @@ func TestFullContextGivesAFailedReport(t *testing.T) {
                "reply: It failed.",
        }, test.Log(t))
        require.Equal(t, subagentFailed, test.events.LastEvent("work").Status)
                "reply: It failed.",
        }, test.Log(t))
        require.Equal(t, subagentFailed, test.events.LastEvent("work").Status)

-       require.Equal(t, "subagent "+name+" started\nsubagent "+name+" failed after 0s: create model response: model call: HTTP 400: "+subagentTestFullContext+"\n", test.logs.String())
+       require.Equal(t, "<6>subagent started name="+name+"\n<3>subagent failed name="+name+" after=0s: create model response: model call: HTTP 400: "+subagentTestFullContext+"\n", test.logs.String())

 }
 
 func TestSubagentHasItsOwnEffortAndNoSpawn(t *testing.T) {
 }
 
 func TestSubagentHasItsOwnEffortAndNoSpawn(t *testing.T) {


@@ -384,7 +385,7 @@ func TestStopEndsASubagentAndItsCommand(t *testing.T) {
                "work: " + subagentReport(name, []string{"stopped"}),
        }, test.Log(t))
        require.Equal(t, subagentStopped, test.events.LastEvent("work").Status)
                "work: " + subagentReport(name, []string{"stopped"}),
        }, test.Log(t))
        require.Equal(t, subagentStopped, test.events.LastEvent("work").Status)

-       require.Equal(t, "subagent "+name+" started\nsubagent "+name+" stopped after 0s\n", test.logs.String())
+       require.Equal(t, "<6>subagent started name="+name+"\n<6>subagent stopped name="+name+" after=0s\n", test.logs.String())

 
        log, err := subagent.Show()
        require.NoError(t, err)
 
        log, err := subagent.Show()
        require.NoError(t, err)


@@ -456,7 +457,7 @@ func TestRestartResumesTheCutSubagents(t *testing.T) {
        require.NoError(t, err)
 
        first := &TurnEventRecorder{}
        require.NoError(t, err)
 
        first := &TurnEventRecorder{}

-       loop, _, stop := subagentTestStart(t, agent, server, first)
+       loop, _, stop := subagentTestStart(t, agent, server, first, discardLog())

        _, err = loop.runs.Spawn(t.Context(), []string{"Build the project."}, nil)
        require.NoError(t, err)
 
        _, err = loop.runs.Spawn(t.Context(), []string{"Build the project."}, nil)
        require.NoError(t, err)
 


@@ -474,7 +475,7 @@ func TestRestartResumesTheCutSubagents(t *testing.T) {
        restarted.Store(true)
 
        second := &TurnEventRecorder{}
        restarted.Store(true)
 
        second := &TurnEventRecorder{}

-       loop, memory, stop := subagentTestStart(t, agent, server, second)
+       loop, memory, stop := subagentTestStart(t, agent, server, second, discardLog())

        defer stop()
 
        second.WaitFor(t, "idle", 1)
        defer stop()
 
        second.WaitFor(t, "idle", 1)


@@ -506,7 +507,8 @@ func TestRestartReportsASubagentThatCannotGoOn(t *testing.T) {
        require.NoError(t, os.WriteFile(filepath.Join(agent.dir, subagentWorkFileName), []byte(`{"running": ["BlueFox"]}`), 0o600))
 
        events := &TurnEventRecorder{}
        require.NoError(t, os.WriteFile(filepath.Join(agent.dir, subagentWorkFileName), []byte(`{"running": ["BlueFox"]}`), 0o600))
 
        events := &TurnEventRecorder{}

-       _, memory, stop := subagentTestStart(t, agent, server, events)
+       logs := &SyncBuffer{}
+       _, memory, stop := subagentTestStart(t, agent, server, events, daemonTestLogger(logs))

        defer stop()
 
        events.WaitFor(t, "idle", 1)
        defer stop()
 
        events.WaitFor(t, "idle", 1)


@@ -516,6 +518,7 @@ func TestRestartReportsASubagentThatCannotGoOn(t *testing.T) {
                "reply: a line",
        }, subagentTestChat(t, memory))
        require.Equal(t, subagentFailed, events.LastEvent("work").Status)
                "reply: a line",
        }, subagentTestChat(t, memory))
        require.Equal(t, subagentFailed, events.LastEvent("work").Status)

+       require.Equal(t, "<3>subagent lost at restart name=BlueFox: no agent BlueFox\n", logs.String())

 
        data, err := os.ReadFile(filepath.Join(agent.dir, subagentWorkFileName))
        require.NoError(t, err)
 
        data, err := os.ReadFile(filepath.Join(agent.dir, subagentWorkFileName))
        require.NoError(t, err)


@@ -525,7 +528,7 @@ func TestRestartReportsASubagentThatCannotGoOn(t *testing.T) {
 // subagentTestStart runs a loop of agent with its memory and subagents in the
 // agent directory, as the daemon does. The returned function stops the loop
 // and closes the files.
 // subagentTestStart runs a loop of agent with its memory and subagents in the
 // agent directory, as the daemon does. The returned function stops the loop
 // and closes the files.

-func subagentTestStart(t *testing.T, agent *Agent, server *ModelFake, events *TurnEventRecorder) (*TurnLoop, *Memory, func()) {
+func subagentTestStart(t *testing.T, agent *Agent, server *ModelFake, events *TurnEventRecorder, logger *slog.Logger) (*TurnLoop, *Memory, func()) {

        t.Helper()
 
        agent.config.Workdir = t.TempDir()
        t.Helper()
 
        agent.config.Workdir = t.TempDir()


@@ -536,7 +539,7 @@ func subagentTestStart(t *testing.T, agent *Agent, server *ModelFake, events *Tu
        subagents := newSubagents(filepath.Join(agent.dir, subagentDirName), clock.Now, subagentNameRandom)
        client := newModelClient(server.URL, ModelAPIKey(modelTestKey), agent.CacheKey(), filepath.Join(agent.dir, "usage.jsonl"))
        whatsapp, _, _ := whatsappStartTest(t, t.TempDir(), clock)
        subagents := newSubagents(filepath.Join(agent.dir, subagentDirName), clock.Now, subagentNameRandom)
        client := newModelClient(server.URL, ModelAPIKey(modelTestKey), agent.CacheKey(), filepath.Join(agent.dir, "usage.jsonl"))
        whatsapp, _, _ := whatsappStartTest(t, t.TempDir(), clock)

-       loop, err := newTurnLoop(agent, memory, subagents, whatsapp, newTestSchedules(t, clock.Now), client, clock.Now, discardLog(), events.Add)
+       loop, err := newTurnLoop(agent, memory, subagents, whatsapp, newTestSchedules(t, clock.Now), client, clock.Now, logger, events.Add)

        require.NoError(t, err)
 
        ctx, cancel := context.WithCancel(t.Context())
        require.NoError(t, err)
 
        ctx, cancel := context.WithCancel(t.Context())

diff --git a/telegram.go b/telegram.go
index 2a9345a3a4b6823c0a17039c207dcf437f12d640..4e2bf7cd3dbf92736c201650ad087043a2502c4e 100644 (file)
--- a/telegram.go
+++ b/telegram.go
@@ -7,7 +7,7 @@ import (
        "errors"
        "fmt"
        "io"
        "errors"
        "fmt"
        "io"

-       "log"
+       "log/slog"

        "net/http"
        "os"
        "path/filepath"
        "net/http"
        "os"
        "path/filepath"


@@ -97,7 +97,7 @@ func loadTelegramConfig(dir string) (TelegramConfig, bool, error) {
 // newTelegramBot returns the bot of owner on api. The offset file is at
 // offsetPath, and logger gets the failures. No log line holds the text of a
 // message.
 // newTelegramBot returns the bot of owner on api. The offset file is at
 // offsetPath, and logger gets the failures. No log line holds the text of a
 // message.

-func newTelegramBot(api *TelegramAPI, owner int64, offsetPath string, logger *log.Logger) *TelegramBot {
+func newTelegramBot(api *TelegramAPI, owner int64, offsetPath string, logger *slog.Logger) *TelegramBot {

        return &TelegramBot{
                api:        api,
                owner:      owner,
        return &TelegramBot{
                api:        api,
                owner:      owner,


@@ -154,7 +154,7 @@ type TelegramBot struct {
        api        *TelegramAPI
        owner      int64
        offsetPath string
        api        *TelegramAPI
        owner      int64
        offsetPath string

-       logger     *log.Logger
+       logger     *slog.Logger

        minWait    time.Duration
        maxWait    time.Duration
 
        minWait    time.Duration
        maxWait    time.Duration
 


@@ -379,7 +379,7 @@ func (b *TelegramBot) pause(ctx context.Context, outage *TelegramOutage, err err
 func (b *TelegramBot) handle(ctx context.Context, l *TurnLoop, whatsapp *WhatsApp, update TelegramUpdate) error {
        message := update.Message
        if message == nil || message.Chat.Type != "private" || message.Chat.ID != b.owner || message.From == nil || message.From.ID != b.owner {
 func (b *TelegramBot) handle(ctx context.Context, l *TurnLoop, whatsapp *WhatsApp, update TelegramUpdate) error {
        message := update.Message
        if message == nil || message.Chat.Type != "private" || message.Chat.ID != b.owner || message.From == nil || message.From.ID != b.owner {

-               b.logger.Print("message ignored: not from the owner")
+               b.logger.Info("message ignored: not from the owner")

 
                return nil
        }
 
                return nil
        }


@@ -440,7 +440,7 @@ func (b *TelegramBot) deliver(ctx context.Context, part TelegramPart) {
                var answer *TelegramError
 
                if len(part.entities) > 0 && errors.As(err, &answer) && answer.Status == http.StatusBadRequest {
                var answer *TelegramError
 
                if len(part.entities) > 0 && errors.As(err, &answer) && answer.Status == http.StatusBadRequest {

-                       b.logger.Printf("reply sent as plain text: %v", err)
+                       b.logger.Warn("reply sent as plain text", "err", err)

 
                        part.entities = nil
 
 
                        part.entities = nil
 


@@ -448,7 +448,7 @@ func (b *TelegramBot) deliver(ctx context.Context, part TelegramPart) {
                }
 
                if !retry {
                }
 
                if !retry {

-                       b.logger.Printf("reply lost: %v", err)
+                       b.logger.Error("reply lost", "err", err)

 
                        return
                }
 
                        return
                }


@@ -479,7 +479,7 @@ func (b *TelegramBot) deliverRich(ctx context.Context, markdown string) {
                }
 
                if telegramRejected(err) {
                }
 
                if telegramRejected(err) {

-                       b.logger.Printf("reply sent with simple formatting: %v", err)
+                       b.logger.Warn("reply sent with simple formatting", "err", err)

 
                        for _, part := range telegramReplyParts(telegramUnescapeTags(markdown)) {
                                b.deliver(ctx, part)
 
                        for _, part := range telegramReplyParts(telegramUnescapeTags(markdown)) {
                                b.deliver(ctx, part)


@@ -489,7 +489,7 @@ func (b *TelegramBot) deliverRich(ctx context.Context, markdown string) {
                }
 
                if !retry {
                }
 
                if !retry {

-                       b.logger.Printf("reply lost: %v", err)
+                       b.logger.Error("reply lost", "err", err)

 
                        return
                }
 
                        return
                }


@@ -520,7 +520,7 @@ func (b *TelegramBot) notice(text string) {
 // nothing. The next answer of Telegram logs back and the length of the outage.
 // loss and back say what the user loses and gets again.
 type TelegramOutage struct {
 // nothing. The next answer of Telegram logs back and the length of the outage.
 // loss and back say what the user loses and gets again.
 type TelegramOutage struct {

-       logger *log.Logger
+       logger *slog.Logger

        loss   string
        back   string
        start  time.Time
        loss   string
        back   string
        start  time.Time


@@ -533,7 +533,7 @@ func (o *TelegramOutage) Fail(err error, delay time.Duration) {
        }
 
        o.start = time.Now()
        }
 
        o.start = time.Now()

-       o.logger.Printf("%s: %v (retry in %s)", o.loss, err, durationText(delay))
+       o.logger.Warn(o.loss, "err", err, "retry", delay)

 }
 
 // End logs the end of the outage that runs, with its length.
 }
 
 // End logs the end of the outage that runs, with its length.


@@ -542,7 +542,7 @@ func (o *TelegramOutage) End() {
                return
        }
 
                return
        }
 

-       o.logger.Printf("%s after %s", o.back, durationText(time.Since(o.start)))
+       o.logger.Info(o.back, "after", time.Since(o.start))

 
        o.start = time.Time{}
 }
 
        o.start = time.Time{}
 }

diff --git a/telegram_test.go b/telegram_test.go
index f1a76b66609b9fd357895edc951e3819ecedfb50..2166bdfd3106adf159f0c84a8ac9eb5d5e8e65ae 100644 (file)
--- a/telegram_test.go
+++ b/telegram_test.go
@@ -1,7 +1,6 @@
 package main
 
 import (
 package main
 
 import (

-       "log"

        "net/http"
        "os"
        "path/filepath"
        "net/http"
        "os"
        "path/filepath"


@@ -76,7 +75,7 @@ func TestBotIgnoresEveryoneButTheOwner(t *testing.T) {
        require.Empty(t, telegram.Sent())
        require.NotContains(t, terminal.Output(), "secret")
        require.NotContains(t, logs.String(), "secret")
        require.Empty(t, telegram.Sent())
        require.NotContains(t, terminal.Output(), "secret")
        require.NotContains(t, logs.String(), "secret")

-       require.Contains(t, logs.String(), "message ignored")
+       require.Contains(t, logs.String(), "<6>message ignored")

 }
 
 func TestBotAnswersThatOnlyTextIsSupported(t *testing.T) {
 }
 
 func TestBotAnswersThatOnlyTextIsSupported(t *testing.T) {


@@ -266,8 +265,10 @@ func TestBotTriesAgainAfterFailures(t *testing.T) {
        })
 
        telegramWaitForSent(t, telegram, "ok")
        })
 
        telegramWaitForSent(t, telegram, "ok")

-       require.Contains(t, logs.String(), "502")
-       require.Contains(t, logs.String(), "429")
+       require.Contains(t, logs.String(), "<4>receive failed retry=1ms: 502")
+       require.Contains(t, logs.String(), "<6>receive back after=")
+       require.Contains(t, logs.String(), "<4>send failed retry=1s: 429")
+       require.Contains(t, logs.String(), "<6>send back after=")

        require.NotContains(t, logs.String(), telegramTestToken)
 }
 
        require.NotContains(t, logs.String(), telegramTestToken)
 }
 


@@ -292,8 +293,8 @@ func TestDeliverTriesAgainAfterATimeout(t *testing.T) {
 
        require.Equal(t, []string{"hello"}, telegram.Sent())
        require.Len(t, telegram.Calls(), 2)
 
        require.Equal(t, []string{"hello"}, telegram.Sent())
        require.Len(t, telegram.Calls(), 2)

-       require.Contains(t, logs.String(), "send failed: no answer in 50ms (retry in 1ms)\n")
-       require.Contains(t, logs.String(), "send back after ")
+       require.Contains(t, logs.String(), "<4>send failed retry=1ms: no answer in 50ms\n")
+       require.Contains(t, logs.String(), "<6>send back after=")

        require.Equal(t, 2, strings.Count(logs.String(), "\n"))
        require.NotContains(t, logs.String(), telegramTestToken)
 }
        require.Equal(t, 2, strings.Count(logs.String(), "\n"))
        require.NotContains(t, logs.String(), telegramTestToken)
 }


@@ -376,7 +377,7 @@ func TestRichMessageFailures(t *testing.T) {
                        methods: []string{"sendRichMessage", "sendMessage"},
                        sent:    []string{"a secret word"},
                        lines:   1,
                        methods: []string{"sendRichMessage", "sendMessage"},
                        sent:    []string{"a secret word"},
                        lines:   1,

-                       logText: "reply sent with simple formatting",
+                       logText: "<4>reply sent with simple formatting",

                },
                {
                        name:    "unknown method sends the reply once with entities",
                },
                {
                        name:    "unknown method sends the reply once with entities",


@@ -385,7 +386,7 @@ func TestRichMessageFailures(t *testing.T) {
                        methods: []string{"sendRichMessage", "sendMessage"},
                        sent:    []string{"a secret word"},
                        lines:   1,
                        methods: []string{"sendRichMessage", "sendMessage"},
                        sent:    []string{"a secret word"},
                        lines:   1,

-                       logText: "reply sent with simple formatting",
+                       logText: "<4>reply sent with simple formatting",

                },
                {
                        name:    "rate limit tries the rich message again",
                },
                {
                        name:    "rate limit tries the rich message again",


@@ -393,7 +394,7 @@ func TestRichMessageFailures(t *testing.T) {
                        methods: []string{"sendRichMessage", "sendRichMessage"},
                        sent:    []string{"a **secret** word"},
                        lines:   2,
                        methods: []string{"sendRichMessage", "sendRichMessage"},
                        sent:    []string{"a **secret** word"},
                        lines:   2,

-                       logText: "send failed: 429",
+                       logText: "<4>send failed retry=1s: 429",

                },
                {
                        name:    "server error tries the rich message again",
                },
                {
                        name:    "server error tries the rich message again",


@@ -401,7 +402,7 @@ func TestRichMessageFailures(t *testing.T) {
                        methods: []string{"sendRichMessage", "sendRichMessage"},
                        sent:    []string{"a **secret** word"},
                        lines:   2,
                        methods: []string{"sendRichMessage", "sendRichMessage"},
                        sent:    []string{"a **secret** word"},
                        lines:   2,

-                       logText: "send failed: 500",
+                       logText: "<4>send failed retry=1ms: 500",

                },
                {
                        name:    "other refusal drops the reply",
                },
                {
                        name:    "other refusal drops the reply",


@@ -409,7 +410,7 @@ func TestRichMessageFailures(t *testing.T) {
                        always:  true,
                        methods: []string{"sendRichMessage"},
                        lines:   1,
                        always:  true,
                        methods: []string{"sendRichMessage"},
                        lines:   1,

-                       logText: "reply lost: 403",
+                       logText: "<3>reply lost: 403",

                },
        }
 
                },
        }
 


@@ -443,6 +444,11 @@ func TestRichMessageFailures(t *testing.T) {
                        require.Equal(t, tc.sent, telegram.Sent())
                        require.Equal(t, tc.lines, strings.Count(logs.String(), "\n"))
                        require.Contains(t, logs.String(), tc.logText)
                        require.Equal(t, tc.sent, telegram.Sent())
                        require.Equal(t, tc.lines, strings.Count(logs.String(), "\n"))
                        require.Contains(t, logs.String(), tc.logText)

+
+                       if tc.lines == 2 {
+                               require.Contains(t, logs.String(), "<6>send back after=")
+                       }
+

                        require.NotContains(t, logs.String(), telegramTestToken)
                        require.NotContains(t, logs.String(), "secret word")
 
                        require.NotContains(t, logs.String(), telegramTestToken)
                        require.NotContains(t, logs.String(), "secret word")
 


@@ -598,11 +604,27 @@ func TestRefusedEntitiesGoAgainAsPlainText(t *testing.T) {
        require.Nil(t, calls[1].params["entities"])
        require.Equal(t, []string{"a secret word"}, telegram.Sent())
        require.Equal(t, 1, strings.Count(logs.String(), "\n"))
        require.Nil(t, calls[1].params["entities"])
        require.Equal(t, []string{"a secret word"}, telegram.Sent())
        require.Equal(t, 1, strings.Count(logs.String(), "\n"))

-       require.Contains(t, logs.String(), "reply sent as plain text")
+       require.Contains(t, logs.String(), "<4>reply sent as plain text")

        require.NotContains(t, logs.String(), telegramTestToken)
        require.NotContains(t, logs.String(), "secret word")
 }
 
        require.NotContains(t, logs.String(), telegramTestToken)
        require.NotContains(t, logs.String(), "secret word")
 }
 

+func TestBotLogsALostPlainReplyAsAnError(t *testing.T) {
+       telegram := newTelegramFake(t)
+       telegram.fail = func(call TelegramFakeCall) (int, string) {
+               if call.method == "sendMessage" {
+                       return http.StatusForbidden, "Forbidden"
+               }
+
+               return 0, ""
+       }
+
+       bot, logs := telegramStartTestBot(t, telegram)
+       bot.deliver(t.Context(), TelegramPart{text: "secret reply"})
+       require.Equal(t, "<3>reply lost: 403 Forbidden\n", logs.String())
+       require.Empty(t, telegram.Sent())
+}
+

 func TestBotLogsNoTokenWhenTheNetworkFails(t *testing.T) {
        telegram := newTelegramFake(t)
        telegram.Close()
 func TestBotLogsNoTokenWhenTheNetworkFails(t *testing.T) {
        telegram := newTelegramFake(t)
        telegram.Close()


@@ -611,7 +633,7 @@ func TestBotLogsNoTokenWhenTheNetworkFails(t *testing.T) {
        daemonStartTestWithBot(t, newModelFake(t), bot)
 
        require.Eventually(t, func() bool {
        daemonStartTestWithBot(t, newModelFake(t), bot)
 
        require.Eventually(t, func() bool {

-               return strings.Contains(logs.String(), "receive failed: no answer: ")
+               return strings.Contains(logs.String(), "<4>receive failed retry=1ms: no answer: ")

        }, 10*time.Second, time.Millisecond)
        require.NotContains(t, logs.String(), telegramTestToken)
 }
        }, 10*time.Second, time.Millisecond)
        require.NotContains(t, logs.String(), telegramTestToken)
 }


@@ -646,8 +668,8 @@ func TestBotLogsAnOutageOnlyAtItsStartAndEnd(t *testing.T) {
 
        lines := strings.Split(strings.TrimSuffix(logs.String(), "\n"), "\n")
        require.Len(t, lines, 2)
 
        lines := strings.Split(strings.TrimSuffix(logs.String(), "\n"), "\n")
        require.Len(t, lines, 2)

-       require.Equal(t, "receive failed: 502 Bad Gateway (retry in 1ms)", lines[0])
-       require.Regexp(t, `^receive back after [0-9]+m?s$`, lines[1])
+       require.Equal(t, "<4>receive failed retry=1ms: 502 Bad Gateway", lines[0])
+       require.Regexp(t, `^<6>receive back after=[0-9]+m?s$`, lines[1])

        require.NotContains(t, logs.String(), "secret word")
        require.NotContains(t, logs.String(), strconv.FormatInt(telegramTestOwner, 10))
 }
        require.NotContains(t, logs.String(), "secret word")
        require.NotContains(t, logs.String(), strconv.FormatInt(telegramTestOwner, 10))
 }


@@ -884,7 +906,7 @@ func telegramStartTestBot(t *testing.T, server *TelegramFake) (*TelegramBot, *Sy
        t.Helper()
 
        logs := &SyncBuffer{}
        t.Helper()
 
        logs := &SyncBuffer{}

-       bot := newTelegramBot(newTelegramAPI(server.URL, telegramTestToken), telegramTestOwner, filepath.Join(t.TempDir(), telegramOffsetFileName), log.New(logs, "", 0))
+       bot := newTelegramBot(newTelegramAPI(server.URL, telegramTestToken), telegramTestOwner, filepath.Join(t.TempDir(), telegramOffsetFileName), daemonTestLogger(logs))

        bot.minWait = time.Millisecond
        bot.maxWait = 10 * time.Millisecond
 
        bot.minWait = time.Millisecond
        bot.maxWait = 10 * time.Millisecond
 

diff --git a/turn.go b/turn.go
index 42886049ffb934582fea0259145aa85e054d4863..637d783b70dfb8c5eb80eb521e7e0510b1db13fc 100644 (file)
--- a/turn.go
+++ b/turn.go
@@ -4,7 +4,7 @@ import (
        "context"
        "errors"
        "fmt"
        "context"
        "errors"
        "fmt"

-       "log"
+       "log/slog"

        "path/filepath"
        "sync"
        "time"
        "path/filepath"
        "sync"
        "time"


@@ -14,7 +14,7 @@ import (
 // WhatsApp link and the schedules of its tools. Its calls go through client,
 // and notify gets each event. The clock gives the date of a turn. logger gets
 // the failed turns and the ends of the subagents.
 // WhatsApp link and the schedules of its tools. Its calls go through client,
 // and notify gets each event. The clock gives the date of a turn. logger gets
 // the failed turns and the ends of the subagents.

-func newTurnLoop(agent *Agent, memory *Memory, subagents *Subagents, whatsapp *WhatsApp, schedules *Schedules, client ChainClient, clock func() time.Time, logger *log.Logger, notify func(Event)) (*TurnLoop, error) {
+func newTurnLoop(agent *Agent, memory *Memory, subagents *Subagents, whatsapp *WhatsApp, schedules *Schedules, client ChainClient, clock func() time.Time, logger *slog.Logger, notify func(Event)) (*TurnLoop, error) {

        layout, err := loadViewLayout(filepath.Join(agent.dir, viewLayoutFileName))
        if err != nil {
                return nil, err
        layout, err := loadViewLayout(filepath.Join(agent.dir, viewLayoutFileName))
        if err != nil {
                return nil, err


@@ -92,7 +92,7 @@ type TurnLoop struct {
        runs   *SubagentRuns
        layout *ViewLayout
        clock  func() time.Time
        runs   *SubagentRuns
        layout *ViewLayout
        clock  func() time.Time

-       logger *log.Logger
+       logger *slog.Logger

        notify func(Event)
        wake   chan struct{}
 
        notify func(Event)
        wake   chan struct{}
 


@@ -334,7 +334,7 @@ func (l *TurnLoop) turn(ctx context.Context) error {
        err := l.chain(ctx)
        if err != nil && !errors.Is(err, errChainLogWrite) {
                if ctx.Err() == nil {
        err := l.chain(ctx)
        if err != nil && !errors.Is(err, errChainLogWrite) {
                if ctx.Err() == nil {

-                       l.logger.Printf("turn failed: %v", err)
+                       l.logger.Error("turn failed", "err", err)

                }
 
                l.notify(Event{
                }
 
                l.notify(Event{

diff --git a/turn_test.go b/turn_test.go
index 81739068505100943dd013356a7d28212efa98db..949c0b8fe93b550c973d480336e5163f96438555 100644 (file)
--- a/turn_test.go
+++ b/turn_test.go
@@ -3,7 +3,6 @@ package main
 import (
        "context"
        "encoding/json"
 import (
        "context"
        "encoding/json"

-       "log"

        "net/http"
        "path/filepath"
        "strings"
        "net/http"
        "path/filepath"
        "strings"


@@ -225,7 +224,7 @@ func TestFailedCallEndsTheTurnWithoutARetry(t *testing.T) {
        require.Equal(t, 1, server.Calls())
        require.Contains(t, test.events.Last("error"), "HTTP 503")
        require.Equal(t, 1, strings.Count(test.logs.String(), "\n"))
        require.Equal(t, 1, server.Calls())
        require.Contains(t, test.events.Last("error"), "HTTP 503")
        require.Equal(t, 1, strings.Count(test.logs.String(), "\n"))

-       require.Contains(t, test.logs.String(), "turn failed: ")
+       require.Contains(t, test.logs.String(), "<3>turn failed: ")

        require.Contains(t, test.logs.String(), "HTTP 503")
        require.NotContains(t, test.logs.String(), "hello")
 }
        require.Contains(t, test.logs.String(), "HTTP 503")
        require.NotContains(t, test.logs.String(), "hello")
 }


@@ -407,7 +406,7 @@ func newTestTurnLoopWith(t *testing.T, server *ModelFake, summarizer Summarizer)
 
        client := newModelClient(server.URL, ModelAPIKey(modelTestKey), agent.CacheKey(), test.usagePath)
        whatsapp, _, _ := whatsappStartTest(t, t.TempDir(), clock)
 
        client := newModelClient(server.URL, ModelAPIKey(modelTestKey), agent.CacheKey(), test.usagePath)
        whatsapp, _, _ := whatsappStartTest(t, t.TempDir(), clock)

-       test.loop, err = newTurnLoop(agent, memory, newTestSubagents(t), whatsapp, newTestSchedules(t, clock.Now), client, clock.Now, log.New(test.logs, "", 0), test.events.Add)
+       test.loop, err = newTurnLoop(agent, memory, newTestSubagents(t), whatsapp, newTestSchedules(t, clock.Now), client, clock.Now, daemonTestLogger(test.logs), test.events.Add)

        require.NoError(t, err)
 
        ctx, cancel := context.WithCancel(t.Context())
        require.NoError(t, err)
 
        ctx, cancel := context.WithCancel(t.Context())

diff --git a/whatsapp.go b/whatsapp.go
index 6e1e1e62211926da5257877f16f1ef21c71f6cfa..95e1d54ea01e80f8216f29e38d63a56a479cc07a 100644 (file)
--- a/whatsapp.go
+++ b/whatsapp.go
@@ -4,7 +4,7 @@ import (
        "context"
        "errors"
        "fmt"
        "context"
        "errors"
        "fmt"

-       "log"
+       "log/slog"

        "net/url"
        "os"
        "path/filepath"
        "net/url"
        "os"
        "path/filepath"


@@ -103,7 +103,7 @@ type WhatsAppClient interface {
 // the account, so a file that another user can read is an error. The clock
 // gives the times of the status, logger gets the failures, and newClient makes
 // the client of a device with its event handler.
 // the account, so a file that another user can read is an error. The clock
 // gives the times of the status, logger gets the failures, and newClient makes
 // the client of a device with its event handler.

-func openWhatsApp(ctx context.Context, dir string, clock func() time.Time, logger *log.Logger, newClient func(device *store.Device, handle func(event any) bool) WhatsAppClient) (*WhatsApp, error) {
+func openWhatsApp(ctx context.Context, dir string, clock func() time.Time, logger *slog.Logger, newClient func(device *store.Device, handle func(event any) bool) WhatsAppClient) (*WhatsApp, error) {

        w := &WhatsApp{
                dir:         filepath.Join(dir, whatsappDirName),
                clock:       clock,
        w := &WhatsApp{
                dir:         filepath.Join(dir, whatsappDirName),
                clock:       clock,


@@ -179,7 +179,7 @@ func openWhatsApp(ctx context.Context, dir string, clock func() time.Time, logge
 type WhatsApp struct {
        dir         string
        clock       func() time.Time
 type WhatsApp struct {
        dir         string
        clock       func() time.Time

-       logger      *log.Logger
+       logger      *slog.Logger

        newClient   func(device *store.Device, handle func(event any) bool) WhatsAppClient
        noticeDelay time.Duration
        requests    chan WhatsAppRequest
        newClient   func(device *store.Device, handle func(event any) bool) WhatsAppClient
        noticeDelay time.Duration
        requests    chan WhatsAppRequest


@@ -487,7 +487,7 @@ func (w *WhatsApp) connect(ctx context.Context) bool {
        w.mutex.Unlock()
 
        if first {
        w.mutex.Unlock()
 
        if first {

-               w.logger.Printf("first connect failed, retrying: %s", cause)
+               w.logger.Warn("first connect failed, retrying", "err", cause)

        }
 
        return true
        }
 
        return true


@@ -538,7 +538,7 @@ func (w *WhatsApp) loggedOut(ctx context.Context, l *TurnLoop) error {
                return nil
        }
 
                return nil
        }
 

-       w.logger.Print("logged out by the phone, run /whatsapp pair PHONE")
+       w.logger.Error("logged out by the phone, run /whatsapp pair PHONE")

 
        err := w.inbox.deliver(ctx, l, w.link(), true)
        if err != nil {
 
        err := w.inbox.deliver(ctx, l, w.link(), true)
        if err != nil {


@@ -547,12 +547,12 @@ func (w *WhatsApp) loggedOut(ctx context.Context, l *TurnLoop) error {
 
        err = w.removeSession()
        if err != nil {
 
        err = w.removeSession()
        if err != nil {

-               w.logger.Printf("session delete failed: %v", err)
+               w.logger.Error("session delete failed", "err", err)

        }
 
        err = l.note("WhatsApp was unlinked from the phone.")
        if err != nil {
        }
 
        err = l.note("WhatsApp was unlinked from the phone.")
        if err != nil {

-               w.logger.Printf("chat note failed: %v", err)
+               w.logger.Error("chat note failed", "err", err)

        }
 
        w.broadcast("WhatsApp was unlinked from the phone. Run /whatsapp pair PHONE to link it again.")
        }
 
        w.broadcast("WhatsApp was unlinked from the phone. Run /whatsapp pair PHONE to link it again.")


@@ -599,11 +599,11 @@ func (w *WhatsApp) unlink(ctx context.Context, l *TurnLoop, answer func(text str
                return nil
        }
 
                return nil
        }
 

-       w.logger.Print("unlinked")
+       w.logger.Info("unlinked")

 
        err = l.note("WhatsApp is unlinked.")
        if err != nil {
 
        err = l.note("WhatsApp is unlinked.")
        if err != nil {

-               w.logger.Printf("chat note failed: %v", err)
+               w.logger.Error("chat note failed", "err", err)

        }
 
        if client == nil || logoutErr != nil {
        }
 
        if client == nil || logoutErr != nil {


@@ -751,11 +751,11 @@ func (w *WhatsApp) pair(ctx, runCtx context.Context, l *TurnLoop, phone string,
                        linked = true
 
                        w.linkedBy(client)
                        linked = true
 
                        w.linkedBy(client)

-                       w.logger.Print("linked")
+                       w.logger.Info("linked")

 
                        err = l.note("WhatsApp is linked.")
                        if err != nil {
 
                        err = l.note("WhatsApp is linked.")
                        if err != nil {

-                               w.logger.Printf("chat note failed: %v", err)
+                               w.logger.Error("chat note failed", "err", err)

                        }
 
                        answer("WhatsApp is linked to +" + phone + ".")
                        }
 
                        answer("WhatsApp is linked to +" + phone + ".")


@@ -848,6 +848,10 @@ func (w *WhatsApp) handle(event any) bool {
 
        var notice, line string
 
 
        var notice, line string
 

+       level := slog.LevelInfo
+
+       var attrs []any
+

        w.mutex.Lock()
 
        switch event := event.(type) {
        w.mutex.Lock()
 
        switch event := event.(type) {


@@ -859,7 +863,8 @@ func (w *WhatsApp) handle(event any) bool {
                case w.disconnectedAt.IsZero():
                        line = "connected"
                default:
                case w.disconnectedAt.IsZero():
                        line = "connected"
                default:

-                       line = "connected again after " + durationText(w.clock().Sub(w.disconnectedAt))
+                       line = "connected again"
+                       attrs = append(attrs, "after", w.clock().Sub(w.disconnectedAt))

                }
 
                w.connected = true
                }
 
                w.connected = true


@@ -876,6 +881,7 @@ func (w *WhatsApp) handle(event any) bool {
        case *events.Disconnected:
                connected := w.connected
                if w.startOutage() {
        case *events.Disconnected:
                connected := w.connected
                if w.startOutage() {

+                       level = slog.LevelWarn

                        line = "disconnected, retrying"
                        if !connected {
                                line = "first connect failed, retrying"
                        line = "disconnected, retrying"
                        if !connected {
                                line = "first connect failed, retrying"


@@ -893,7 +899,9 @@ func (w *WhatsApp) handle(event any) bool {
                        w.connected = false
                        w.noticed = true
                        notice = "WhatsApp is disconnected and does not connect again by itself: " + event.PermanentDisconnectDescription() + ". Restart the daemon to try again."
                        w.connected = false
                        w.noticed = true
                        notice = "WhatsApp is disconnected and does not connect again by itself: " + event.PermanentDisconnectDescription() + ". Restart the daemon to try again."

-                       line = "disconnected for good, restart to retry: " + whatsappRedact(w.own, event.PermanentDisconnectDescription())
+                       level = slog.LevelError
+                       line = "disconnected for good, restart to retry"
+                       attrs = append(attrs, "err", whatsappRedact(w.own, event.PermanentDisconnectDescription()))

                }
        }
 
                }
        }
 


@@ -904,7 +912,7 @@ func (w *WhatsApp) handle(event any) bool {
        w.mutex.Unlock()
 
        if line != "" {
        w.mutex.Unlock()
 
        if line != "" {

-               w.logger.Print(line)
+               w.logger.Log(context.Background(), level, line, attrs...)

        }
 
        if notice != "" {
        }
 
        if notice != "" {

diff --git a/whatsapp_fake_helper_test.go b/whatsapp_fake_helper_test.go
index 1625fe3b8729b9c3f9240e161797903229462c24..d8bb9bb310a4d15ce31fa45e07026408f6ff0d6a 100644 (file)
--- a/whatsapp_fake_helper_test.go
+++ b/whatsapp_fake_helper_test.go
@@ -3,8 +3,7 @@ package main
 import (
        "context"
        "fmt"
 import (
        "context"
        "fmt"

-       "io"
-       "log"
+       "log/slog"

        "os"
        "path/filepath"
        "slices"
        "os"
        "path/filepath"
        "slices"


@@ -261,7 +260,7 @@ func whatsappStartTest(t *testing.T, dir string, clock *TestClock) (*WhatsApp, *
        }
 
        logs := &SyncBuffer{}
        }
 
        logs := &SyncBuffer{}

-       whatsapp, err := openWhatsApp(t.Context(), dir, clock.Now, log.New(logs, "", 0), fake.newClient)
+       whatsapp, err := openWhatsApp(t.Context(), dir, clock.Now, daemonTestLogger(logs), fake.newClient)

        require.NoError(t, err)
 
        t.Cleanup(func() {
        require.NoError(t, err)
 
        t.Cleanup(func() {


@@ -306,8 +305,8 @@ func whatsappTestSession(t *testing.T, dir string, linked bool) {
 }
 
 // whatsappDiscardLog is a logger for a WhatsApp whose log a test does not read.
 }
 
 // whatsappDiscardLog is a logger for a WhatsApp whose log a test does not read.

-func whatsappDiscardLog() *log.Logger {
-       return log.New(io.Discard, "", 0)
+func whatsappDiscardLog() *slog.Logger {
+       return slog.New(slog.DiscardHandler)

 }
 
 // whatsappTestMessage returns the event of the text message id of sender in
 }
 
 // whatsappTestMessage returns the event of the text message id of sender in

diff --git a/whatsapp_groups.go b/whatsapp_groups.go
index 56676e5264fb363e709b2785bd095c6c9d42c012..ec5c892309e4aa282412730f5be35f95125acdb0 100644 (file)
--- a/whatsapp_groups.go
+++ b/whatsapp_groups.go
@@ -2,7 +2,7 @@ package main
 
 import (
        "context"
 
 import (
        "context"

-       "log"
+       "log/slog"

        "maps"
        "sync"
        "time"
        "maps"
        "sync"
        "time"


@@ -23,7 +23,7 @@ const (
 
 // newWhatsAppGroups returns the names of the groups with no names yet. logger
 // gets the failures of a read.
 
 // newWhatsAppGroups returns the names of the groups with no names yet. logger
 // gets the failures of a read.

-func newWhatsAppGroups(logger *log.Logger) *WhatsAppGroups {
+func newWhatsAppGroups(logger *slog.Logger) *WhatsAppGroups {

        return &WhatsAppGroups{
                logger: logger,
                names:  make(map[string]string),
        return &WhatsAppGroups{
                logger: logger,
                names:  make(map[string]string),


@@ -36,7 +36,7 @@ func newWhatsAppGroups(logger *log.Logger) *WhatsAppGroups {
 // read, and readAt the time of the last read that succeeded. The mutex
 // protects all fields after logger.
 type WhatsAppGroups struct {
 // read, and readAt the time of the last read that succeeded. The mutex
 // protects all fields after logger.
 type WhatsAppGroups struct {

-       logger *log.Logger
+       logger *slog.Logger

 
        mutex   sync.Mutex
        names   map[string]string
 
        mutex   sync.Mutex
        names   map[string]string


@@ -82,7 +82,7 @@ func (g *WhatsAppGroups) read(ctx context.Context, link WhatsAppLink) bool {
 
        groups, err := link.client.GetJoinedGroups(ctx)
        if err != nil {
 
        groups, err := link.client.GetJoinedGroups(ctx)
        if err != nil {

-               g.logger.Printf("group list failed: %s", whatsappRedact(link.own, err.Error()))
+               g.logger.Warn("group list failed", "err", whatsappRedact(link.own, err.Error()))

        }
 
        g.mutex.Lock()
        }
 
        g.mutex.Lock()

diff --git a/whatsapp_groups_test.go b/whatsapp_groups_test.go
new file mode 100644 (file)
index 0000000..5b8e5c7
--- /dev/null
+++ b/whatsapp_groups_test.go
@@ -0,0 +1,36 @@
+package main
+
+import (
+       "context"
+       "errors"
+       "strings"
+       "testing"
+
+       "github.com/stretchr/testify/require"
+       "go.mau.fi/whatsmeow/types"
+)
+
+func TestWhatsAppGroupReadFailureWarnsWithoutLosingNames(t *testing.T) {
+       var logs strings.Builder
+
+       groups := newWhatsAppGroups(daemonTestLogger(&logs))
+       groups.set("group", "Example group")
+
+       client := &WhatsAppGroupsFailure{WhatsAppClient: &WhatsAppFake{}}
+       link := WhatsAppLink{
+               client: client,
+               own:    []string{whatsappTestNumber},
+       }
+
+       require.False(t, groups.read(t.Context(), link))
+       require.Equal(t, "<4>group list failed: no route for OWN\n", logs.String())
+       require.Equal(t, "Example group", groups.name(t.Context(), link, "group"))
+}
+
+type WhatsAppGroupsFailure struct {
+       WhatsAppClient
+}
+
+func (c *WhatsAppGroupsFailure) GetJoinedGroups(_ context.Context) ([]*types.GroupInfo, error) {
+       return nil, errors.New("no route for " + whatsappTestNumber)
+}

diff --git a/whatsapp_test.go b/whatsapp_test.go
index 7a00bbeb3be005ab68a4a345216d57f27e3407df..96ec2df0031cb169310fb99324046ce8e9698bf4 100644 (file)
--- a/whatsapp_test.go
+++ b/whatsapp_test.go
@@ -48,7 +48,7 @@ func TestWhatsAppStatusOfAFirstConnectionThatFailed(t *testing.T) {
                synctest.Wait()
 
                require.Equal(t, "WhatsApp is linked and disconnected since "+time.Now().Format(whatsappTimeLayout)+".", test.whatsapp.Status())
                synctest.Wait()
 
                require.Equal(t, "WhatsApp is linked and disconnected since "+time.Now().Format(whatsappTimeLayout)+".", test.whatsapp.Status())

-               require.Equal(t, "first connect failed, retrying: network unavailable\n", test.logs.String())
+               require.Equal(t, "<4>first connect failed, retrying: network unavailable\n", test.logs.String())

        })
 }
 
        })
 }
 


@@ -91,7 +91,7 @@ func TestWhatsAppRetriesTheFirstConnectionWithCappedBackoff(t *testing.T) {
                time.Sleep(10 * time.Minute)
                synctest.Wait()
                require.Len(t, test.fake.Connections(), 11)
                time.Sleep(10 * time.Minute)
                synctest.Wait()
                require.Len(t, test.fake.Connections(), 11)

-               require.Equal(t, "first connect failed, retrying: network unavailable\nconnected again after "+durationText(outage)+"\n", test.logs.String())
+               require.Equal(t, "<4>first connect failed, retrying: network unavailable\n<6>connected again after="+durationText(outage)+"\n", test.logs.String())

        })
 }
 
        })
 }
 


@@ -139,7 +139,7 @@ func TestWhatsAppLinkedPairRequestKeepsFirstConnectionRetries(t *testing.T) {
                time.Sleep(whatsappRetryLimit)
                synctest.Wait()
                require.Len(t, test.fake.Connections(), 2)
                time.Sleep(whatsappRetryLimit)
                synctest.Wait()
                require.Len(t, test.fake.Connections(), 2)

-               require.Equal(t, "first connect failed, retrying: network unavailable\nconnected again after 2s\n", test.logs.String())
+               require.Equal(t, "<4>first connect failed, retrying: network unavailable\n<6>connected again after=2s\n", test.logs.String())

        })
 }
 
        })
 }
 


@@ -312,9 +312,9 @@ func TestWhatsAppLogsEachChangeOfTheConnectionOnce(t *testing.T) {
        require.True(t, fake.Emit(&events.Connected{}))
 
        require.Equal(t, []string{
        require.True(t, fake.Emit(&events.Connected{}))
 
        require.Equal(t, []string{

-               "connected",
-               "disconnected, retrying",
-               "connected again after 1m25s",
+               "<6>connected",
+               "<4>disconnected, retrying",
+               "<6>connected again after=1m25s",

        }, strings.Split(strings.TrimSuffix(logs.String(), "\n"), "\n"))
        require.NotContains(t, logs.String(), whatsappTestNumber)
        require.NotContains(t, logs.String(), whatsappTestLID)
        }, strings.Split(strings.TrimSuffix(logs.String(), "\n"), "\n"))
        require.NotContains(t, logs.String(), whatsappTestNumber)
        require.NotContains(t, logs.String(), whatsappTestLID)


@@ -388,7 +388,7 @@ func TestWhatsAppCommandsAnswerOnlyTheClientThatAsked(t *testing.T) {
 
 func TestWhatsAppPairsWithACode(t *testing.T) {
        dir := t.TempDir()
 
 func TestWhatsAppPairsWithACode(t *testing.T) {
        dir := t.TempDir()

-       whatsapp, fake, _ := whatsappStartTest(t, dir, newTestClock())
+       whatsapp, fake, logs := whatsappStartTest(t, dir, newTestClock())

        server := newModelFake(t)
        socket, memory := daemonStartTestWithWhatsApp(t, server, nil, whatsapp)
        asking := terminalStartTestClient(t, socket)
        server := newModelFake(t)
        socket, memory := daemonStartTestWithWhatsApp(t, server, nil, whatsapp)
        asking := terminalStartTestClient(t, socket)


@@ -426,6 +426,7 @@ func TestWhatsAppPairsWithACode(t *testing.T) {
        require.Equal(t, "[connected to OneChat]\n", other.Output())
        require.Zero(t, server.Calls())
        require.Equal(t, []string{"WhatsApp is linked."}, whatsappTestLogTexts(t, memory))
        require.Equal(t, "[connected to OneChat]\n", other.Output())
        require.Zero(t, server.Calls())
        require.Equal(t, []string{"WhatsApp is linked."}, whatsappTestLogTexts(t, memory))

+       require.Equal(t, "<6>linked\n", logs.String())

 
        info, err := os.Stat(filepath.Join(dir, whatsappDirName))
        require.NoError(t, err)
 
        info, err := os.Stat(filepath.Join(dir, whatsappDirName))
        require.NoError(t, err)


@@ -560,7 +561,7 @@ func TestWhatsAppUnlink(t *testing.T) {
                        dir := t.TempDir()
                        whatsappTestSession(t, dir, true)
 
                        dir := t.TempDir()
                        whatsappTestSession(t, dir, true)
 

-                       whatsapp, fake, _ := whatsappStartTest(t, dir, newTestClock())
+                       whatsapp, fake, logs := whatsappStartTest(t, dir, newTestClock())

                        fake.logoutErr = tc.logoutErr
                        socket, memory := daemonStartTestWithWhatsApp(t, newModelFake(t), nil, whatsapp)
                        client := terminalStartTestClient(t, socket)
                        fake.logoutErr = tc.logoutErr
                        socket, memory := daemonStartTestWithWhatsApp(t, newModelFake(t), nil, whatsapp)
                        client := terminalStartTestClient(t, socket)


@@ -570,6 +571,7 @@ func TestWhatsAppUnlink(t *testing.T) {
                        client.Type("/whatsapp unlink")
                        client.WaitFor(t, tc.answer)
                        require.Equal(t, 1, fake.Logouts())
                        client.Type("/whatsapp unlink")
                        client.WaitFor(t, tc.answer)
                        require.Equal(t, 1, fake.Logouts())

+                       require.Equal(t, "<6>unlinked\n", logs.String())

                        require.NoFileExists(t, filepath.Join(dir, whatsappDirName, whatsappSessionFileName))
                        require.Equal(t, "WhatsApp is not linked. Run /whatsapp pair PHONE to link it.", whatsapp.Status())
                        require.Equal(t, []string{"WhatsApp is unlinked."}, whatsappTestLogTexts(t, memory))
                        require.NoFileExists(t, filepath.Join(dir, whatsappDirName, whatsappSessionFileName))
                        require.Equal(t, "WhatsApp is not linked. Run /whatsapp pair PHONE to link it.", whatsapp.Status())
                        require.Equal(t, []string{"WhatsApp is unlinked."}, whatsappTestLogTexts(t, memory))


@@ -584,7 +586,7 @@ func TestWhatsAppLogoutFromThePhone(t *testing.T) {
        dir := t.TempDir()
        whatsappTestSession(t, dir, true)
 
        dir := t.TempDir()
        whatsappTestSession(t, dir, true)
 

-       whatsapp, fake, _ := whatsappStartTest(t, dir, newTestClock())
+       whatsapp, fake, logs := whatsappStartTest(t, dir, newTestClock())

        telegram := newTelegramFake(t)
        bot, _ := telegramStartTestBot(t, telegram)
        socket, memory := daemonStartTestWithWhatsApp(t, newModelFake(t), bot, whatsapp)
        telegram := newTelegramFake(t)
        bot, _ := telegramStartTestBot(t, telegram)
        socket, memory := daemonStartTestWithWhatsApp(t, newModelFake(t), bot, whatsapp)


@@ -597,6 +599,7 @@ func TestWhatsAppLogoutFromThePhone(t *testing.T) {
        notice := "WhatsApp was unlinked from the phone. Run /whatsapp pair PHONE to link it again."
        client.WaitFor(t, notice)
        telegramWaitForSent(t, telegram, notice)
        notice := "WhatsApp was unlinked from the phone. Run /whatsapp pair PHONE to link it again."
        client.WaitFor(t, notice)
        telegramWaitForSent(t, telegram, notice)

+       require.Equal(t, "<3>logged out by the phone, run /whatsapp pair PHONE\n", logs.String())

        require.NoFileExists(t, filepath.Join(dir, whatsappDirName, whatsappSessionFileName))
        require.Equal(t, "WhatsApp is not linked. Run /whatsapp pair PHONE to link it.", whatsapp.Status())
        require.Equal(t, []string{"WhatsApp was unlinked from the phone."}, whatsappTestLogTexts(t, memory))
        require.NoFileExists(t, filepath.Join(dir, whatsappDirName, whatsappSessionFileName))
        require.Equal(t, "WhatsApp is not linked. Run /whatsapp pair PHONE to link it.", whatsapp.Status())
        require.Equal(t, []string{"WhatsApp was unlinked from the phone."}, whatsappTestLogTexts(t, memory))


@@ -637,7 +640,7 @@ func TestWhatsAppDisconnectionWithNoRetryGivesANoticeAtOnce(t *testing.T) {
        dir := t.TempDir()
        whatsappTestSession(t, dir, true)
 
        dir := t.TempDir()
        whatsappTestSession(t, dir, true)
 

-       whatsapp, fake, _ := whatsappStartTest(t, dir, newTestClock())
+       whatsapp, fake, logs := whatsappStartTest(t, dir, newTestClock())

        socket, _ := daemonStartTestWithWhatsApp(t, newModelFake(t), nil, whatsapp)
        client := terminalStartTestClient(t, socket)
        client.WaitFor(t, "[connected to OneChat]")
        socket, _ := daemonStartTestWithWhatsApp(t, newModelFake(t), nil, whatsapp)
        client := terminalStartTestClient(t, socket)
        client.WaitFor(t, "[connected to OneChat]")


@@ -645,6 +648,7 @@ func TestWhatsAppDisconnectionWithNoRetryGivesANoticeAtOnce(t *testing.T) {
 
        require.True(t, fake.Emit(&events.StreamReplaced{}))
        client.WaitFor(t, "WhatsApp is disconnected and does not connect again by itself: stream replaced. Restart the daemon to try again.")
 
        require.True(t, fake.Emit(&events.StreamReplaced{}))
        client.WaitFor(t, "WhatsApp is disconnected and does not connect again by itself: stream replaced. Restart the daemon to try again.")

+       require.Equal(t, "<3>disconnected for good, restart to retry: stream replaced\n", logs.String())

 }
 
 func TestWhatsAppLogsNoOwnNumber(t *testing.T) {
 }
 
 func TestWhatsAppLogsNoOwnNumber(t *testing.T) {


@@ -660,7 +664,7 @@ func TestWhatsAppLogsNoOwnNumber(t *testing.T) {
        require.Eventually(t, func() bool {
                return logs.String() != ""
        }, 10*time.Second, time.Millisecond)
        require.Eventually(t, func() bool {
                return logs.String() != ""
        }, 10*time.Second, time.Millisecond)

-       require.Equal(t, "first connect failed, retrying: no route for OWN@s.whatsapp.net and OWN@lid\n", logs.String())
+       require.Equal(t, "<4>first connect failed, retrying: no route for OWN@s.whatsapp.net and OWN@lid\n", logs.String())

 }
 
 func TestWhatsAppPhone(t *testing.T) {
 }
 
 func TestWhatsAppPhone(t *testing.T) {