From: Anderson A. Giacomolli Date: Tue, 10 Nov 2026 01:33:22 +0000 (-0300) Subject: Log daemon events at their slog levels X-Git-Url: http://git.giacomolli.uk/onechat/commitdiff_plain/790279faf0fda789d93a75f6f5996e65d5de4a18 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 5ec220e..ef73896 100644 --- a/daemon.go +++ b/daemon.go @@ -7,7 +7,6 @@ import ( "errors" "fmt" "io" - "log" "net" "os" "path/filepath" @@ -111,19 +110,19 @@ func daemon(ctx context.Context, out io.Writer) (err error) { return err } - linked := "WhatsApp not linked" + linked := "not linked" 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: ")) - logger.Print("Telegram bot started") + logger.Info("Telegram bot started") } 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) } } - -// 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 15426bc..ef1360c 100644 --- a/daemon_log.go +++ b/daemon_log.go @@ -5,10 +5,24 @@ import ( "fmt" "io" "log/slog" + "os" "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. @@ -141,3 +155,13 @@ func daemonLogAttr(line *strings.Builder, group string, attr slog.Attr, cause *s 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 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 bfb4efb..6a4d98c 100644 --- 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", - 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: "", - 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 - daemonLogger(&out, "onechat: ").Print("the agent is ready") + daemonLogger(&out, "onechat: ").Info("the agent is ready") require.Regexp(t, tc.line, out.String()) }) } diff --git a/discard_log_helper_test.go b/discard_log_helper_test.go index 9c24880..ac6fc0e 100644 --- a/discard_log_helper_test.go +++ b/discard_log_helper_test.go @@ -1,11 +1,10 @@ package main import ( - "io" - "log" + "log/slog" ) // 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 7cbcce6..20f46d6 100644 --- a/memory.go +++ b/memory.go @@ -5,7 +5,7 @@ import ( "encoding/json" "errors" "fmt" - "log" + "log/slog" "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. -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 @@ -108,7 +108,7 @@ type Memory struct { cview *View queue *BuildQueue summarizer Summarizer - logger *log.Logger + logger *slog.Logger 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) { - 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. diff --git a/memory_test.go b/memory_test.go index fe050c4..202d4da 100644 --- a/memory_test.go +++ b/memory_test.go @@ -3,7 +3,6 @@ package main import ( "context" "fmt" - "log" "maps" "os" "path/filepath" @@ -184,7 +183,7 @@ func TestMemorySettleFailsWhileABuildFailed(t *testing.T) { 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() { @@ -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) - 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) diff --git a/probe.go b/probe.go index d788fa9..3781cd3 100644 --- a/probe.go +++ b/probe.go @@ -7,7 +7,7 @@ import ( "errors" "fmt" "io" - "log" + "log/slog" "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. - 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) } diff --git a/rebuild.go b/rebuild.go index 91b5ae5..11c6bfc 100644 --- a/rebuild.go +++ b/rebuild.go @@ -7,7 +7,7 @@ import ( "fmt" "io" "io/fs" - "log" + "log/slog" "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) } diff --git a/schedule.go b/schedule.go index d2f53e0..5da024d 100644 --- a/schedule.go +++ b/schedule.go @@ -6,7 +6,7 @@ import ( "encoding/json" "errors" "fmt" - "log" + "log/slog" "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. -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, @@ -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 - logger *log.Logger + logger *slog.Logger check time.Duration changed chan struct{} @@ -281,12 +281,13 @@ func (s *Schedules) deliver(ctx context.Context, l *TurnLoop) error { return err } + attrs := []any{"id", schedule.ID} 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) } diff --git a/schedule_test.go b/schedule_test.go index cb1b06a..3048d75 100644 --- a/schedule_test.go +++ b/schedule_test.go @@ -2,7 +2,6 @@ package main import ( "context" - "log" "os" "path/filepath" "strings" @@ -242,7 +241,7 @@ func TestSchedulesRunStartsATurnWhenDue(t *testing.T) { } 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) @@ -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 ran\n", logs.String()) + require.Equal(t, "<6>schedule ran id=1\n", logs.String()) } func TestSchedulesRunMissedSchedulesOnceAtTheStart(t *testing.T) { @@ -271,7 +270,7 @@ func TestSchedulesRunMissedSchedulesOnceAtTheStart(t *testing.T) { } 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) @@ -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()) - 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) { diff --git a/subagent_run.go b/subagent_run.go index c5e98df..0780393 100644 --- a/subagent_run.go +++ b/subagent_run.go @@ -5,7 +5,7 @@ import ( "encoding/json" "errors" "fmt" - "log" + "log/slog" "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) - logger *log.Logger + logger *slog.Logger 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 { - 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) } } @@ -355,7 +355,7 @@ func (r *SubagentRuns) start(ctx context.Context, run *SubagentRun) error { 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, @@ -470,14 +470,14 @@ func (r *SubagentRuns) run(ctx context.Context, run *SubagentRun) { status = subagentStopped } - length := durationText(r.subagents.clock().Sub(run.started)) + length := r.subagents.clock().Sub(run.started) 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: - 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: - 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) diff --git a/subagent_run_test.go b/subagent_run_test.go index f637dcf..c5ad299 100644 --- a/subagent_run_test.go +++ b/subagent_run_test.go @@ -3,6 +3,7 @@ package main import ( "context" "io" + "log/slog" "net/http" "os" "path/filepath" @@ -69,7 +70,7 @@ func TestSpawnRunsASubagentInTheBackground(t *testing.T) { 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 @@ -197,7 +198,7 @@ func TestFullContextGivesAFailedReport(t *testing.T) { "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) { @@ -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) - 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) @@ -456,7 +457,7 @@ func TestRestartResumesTheCutSubagents(t *testing.T) { 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) @@ -474,7 +475,7 @@ func TestRestartResumesTheCutSubagents(t *testing.T) { 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) @@ -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{} - _, 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) @@ -516,6 +518,7 @@ func TestRestartReportsASubagentThatCannotGoOn(t *testing.T) { "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) @@ -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. -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() @@ -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) - 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()) diff --git a/telegram.go b/telegram.go index 2a9345a..4e2bf7c 100644 --- a/telegram.go +++ b/telegram.go @@ -7,7 +7,7 @@ import ( "errors" "fmt" "io" - "log" + "log/slog" "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. -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, @@ -154,7 +154,7 @@ type TelegramBot struct { api *TelegramAPI owner int64 offsetPath string - logger *log.Logger + logger *slog.Logger 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 { - b.logger.Print("message ignored: not from the owner") + b.logger.Info("message ignored: not from the owner") 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 { - b.logger.Printf("reply sent as plain text: %v", err) + b.logger.Warn("reply sent as plain text", "err", err) part.entities = nil @@ -448,7 +448,7 @@ func (b *TelegramBot) deliver(ctx context.Context, part TelegramPart) { } if !retry { - b.logger.Printf("reply lost: %v", err) + b.logger.Error("reply lost", "err", err) return } @@ -479,7 +479,7 @@ func (b *TelegramBot) deliverRich(ctx context.Context, markdown string) { } 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) @@ -489,7 +489,7 @@ func (b *TelegramBot) deliverRich(ctx context.Context, markdown string) { } if !retry { - b.logger.Printf("reply lost: %v", err) + b.logger.Error("reply lost", "err", err) 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 { - logger *log.Logger + logger *slog.Logger 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.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. @@ -542,7 +542,7 @@ func (o *TelegramOutage) End() { 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{} } diff --git a/telegram_test.go b/telegram_test.go index f1a76b6..2166bdf 100644 --- a/telegram_test.go +++ b/telegram_test.go @@ -1,7 +1,6 @@ package main import ( - "log" "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.Contains(t, logs.String(), "message ignored") + require.Contains(t, logs.String(), "<6>message ignored") } func TestBotAnswersThatOnlyTextIsSupported(t *testing.T) { @@ -266,8 +265,10 @@ func TestBotTriesAgainAfterFailures(t *testing.T) { }) 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) } @@ -292,8 +293,8 @@ func TestDeliverTriesAgainAfterATimeout(t *testing.T) { 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) } @@ -376,7 +377,7 @@ func TestRichMessageFailures(t *testing.T) { 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", @@ -385,7 +386,7 @@ func TestRichMessageFailures(t *testing.T) { 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", @@ -393,7 +394,7 @@ func TestRichMessageFailures(t *testing.T) { 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", @@ -401,7 +402,7 @@ func TestRichMessageFailures(t *testing.T) { 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", @@ -409,7 +410,7 @@ func TestRichMessageFailures(t *testing.T) { 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) + + 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") @@ -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.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") } +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() @@ -611,7 +633,7 @@ func TestBotLogsNoTokenWhenTheNetworkFails(t *testing.T) { 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) } @@ -646,8 +668,8 @@ func TestBotLogsAnOutageOnlyAtItsStartAndEnd(t *testing.T) { 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)) } @@ -884,7 +906,7 @@ func telegramStartTestBot(t *testing.T, server *TelegramFake) (*TelegramBot, *Sy 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 diff --git a/turn.go b/turn.go index 4288604..637d783 100644 --- a/turn.go +++ b/turn.go @@ -4,7 +4,7 @@ import ( "context" "errors" "fmt" - "log" + "log/slog" "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. -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 @@ -92,7 +92,7 @@ type TurnLoop struct { runs *SubagentRuns layout *ViewLayout clock func() time.Time - logger *log.Logger + logger *slog.Logger 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 { - l.logger.Printf("turn failed: %v", err) + l.logger.Error("turn failed", "err", err) } l.notify(Event{ diff --git a/turn_test.go b/turn_test.go index 8173906..949c0b8 100644 --- a/turn_test.go +++ b/turn_test.go @@ -3,7 +3,6 @@ package main import ( "context" "encoding/json" - "log" "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.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") } @@ -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) - 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()) diff --git a/whatsapp.go b/whatsapp.go index 6e1e1e6..95e1d54 100644 --- a/whatsapp.go +++ b/whatsapp.go @@ -4,7 +4,7 @@ import ( "context" "errors" "fmt" - "log" + "log/slog" "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. -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, @@ -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 - logger *log.Logger + logger *slog.Logger 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.logger.Printf("first connect failed, retrying: %s", cause) + w.logger.Warn("first connect failed, retrying", "err", cause) } return true @@ -538,7 +538,7 @@ func (w *WhatsApp) loggedOut(ctx context.Context, l *TurnLoop) error { 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 { @@ -547,12 +547,12 @@ func (w *WhatsApp) loggedOut(ctx context.Context, l *TurnLoop) error { 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 { - 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.") @@ -599,11 +599,11 @@ func (w *WhatsApp) unlink(ctx context.Context, l *TurnLoop, answer func(text str return nil } - w.logger.Print("unlinked") + w.logger.Info("unlinked") 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 { @@ -751,11 +751,11 @@ func (w *WhatsApp) pair(ctx, runCtx context.Context, l *TurnLoop, phone string, linked = true w.linkedBy(client) - w.logger.Print("linked") + w.logger.Info("linked") 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 + ".") @@ -848,6 +848,10 @@ func (w *WhatsApp) handle(event any) bool { var notice, line string + level := slog.LevelInfo + + var attrs []any + 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: - 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 @@ -876,6 +881,7 @@ func (w *WhatsApp) handle(event any) bool { case *events.Disconnected: connected := w.connected if w.startOutage() { + level = slog.LevelWarn 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." - 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.logger.Print(line) + w.logger.Log(context.Background(), level, line, attrs...) } if notice != "" { diff --git a/whatsapp_fake_helper_test.go b/whatsapp_fake_helper_test.go index 1625fe3..d8bb9bb 100644 --- a/whatsapp_fake_helper_test.go +++ b/whatsapp_fake_helper_test.go @@ -3,8 +3,7 @@ package main import ( "context" "fmt" - "io" - "log" + "log/slog" "os" "path/filepath" "slices" @@ -261,7 +260,7 @@ func whatsappStartTest(t *testing.T, dir string, clock *TestClock) (*WhatsApp, * } 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() { @@ -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. -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 diff --git a/whatsapp_groups.go b/whatsapp_groups.go index 56676e5..ec5c892 100644 --- a/whatsapp_groups.go +++ b/whatsapp_groups.go @@ -2,7 +2,7 @@ package main import ( "context" - "log" + "log/slog" "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. -func newWhatsAppGroups(logger *log.Logger) *WhatsAppGroups { +func newWhatsAppGroups(logger *slog.Logger) *WhatsAppGroups { 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 { - logger *log.Logger + logger *slog.Logger 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 { - 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() diff --git a/whatsapp_groups_test.go b/whatsapp_groups_test.go new file mode 100644 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 7a00bbe..96ec2df 100644 --- 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()) - 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) - 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) - 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{ - "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) @@ -388,7 +388,7 @@ func TestWhatsAppCommandsAnswerOnlyTheClientThatAsked(t *testing.T) { 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) @@ -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, "<6>linked\n", logs.String()) 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) - 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) @@ -570,6 +571,7 @@ func TestWhatsAppUnlink(t *testing.T) { 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)) @@ -584,7 +586,7 @@ func TestWhatsAppLogoutFromThePhone(t *testing.T) { 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) @@ -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) + 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)) @@ -637,7 +640,7 @@ func TestWhatsAppDisconnectionWithNoRetryGivesANoticeAtOnce(t *testing.T) { 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]") @@ -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.Equal(t, "<3>disconnected for good, restart to retry: stream replaced\n", logs.String()) } 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.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) {