"errors"
"fmt"
"io"
- "log"
"net"
"os"
"path/filepath"
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) {
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()
-}
"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.
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()
+}
--- /dev/null
+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{},
+ })
+}
{
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$`,
},
}
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())
})
}
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)
}
"encoding/json"
"errors"
"fmt"
- "log"
+ "log/slog"
"os"
"path/filepath"
"strings"
// 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
cview *View
queue *BuildQueue
summarizer Summarizer
- logger *log.Logger
+ logger *slog.Logger
ctx context.Context
cancel context.CancelFunc
workers sync.WaitGroup
// 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.
import (
"context"
"fmt"
- "log"
"maps"
"os"
"path/filepath"
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() {
_, 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)
"errors"
"fmt"
"io"
- "log"
+ "log/slog"
"os"
"path/filepath"
"strconv"
// 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)
}
"fmt"
"io"
"io/fs"
- "log"
+ "log/slog"
"os"
"path/filepath"
"slices"
}
}()
- 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)
}
"encoding/json"
"errors"
"fmt"
- "log"
+ "log/slog"
"os"
"slices"
"strconv"
// 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,
type Schedules struct {
path string
clock func() time.Time
- logger *log.Logger
+ logger *slog.Logger
check time.Duration
changed chan struct{}
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)
}
import (
"context"
- "log"
"os"
"path/filepath"
"strings"
}
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.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) {
}
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)
"[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) {
"encoding/json"
"errors"
"fmt"
- "log"
+ "log/slog"
"maps"
"os"
"path/filepath"
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
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.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,
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)
import (
"context"
"io"
+ "log/slog"
"net/http"
"os"
"path/filepath"
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
"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) {
"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)
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)
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)
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)
"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)
// 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()
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())
"errors"
"fmt"
"io"
- "log"
+ "log/slog"
"net/http"
"os"
"path/filepath"
// 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,
api *TelegramAPI
owner int64
offsetPath string
- logger *log.Logger
+ logger *slog.Logger
minWait time.Duration
maxWait time.Duration
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
}
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
}
if !retry {
- b.logger.Printf("reply lost: %v", err)
+ b.logger.Error("reply lost", "err", err)
return
}
}
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)
}
if !retry {
- b.logger.Printf("reply lost: %v", err)
+ b.logger.Error("reply lost", "err", err)
return
}
// 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
}
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.
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{}
}
package main
import (
- "log"
"net/http"
"os"
"path/filepath"
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) {
})
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.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)
}
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",
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",
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",
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",
always: true,
methods: []string{"sendRichMessage"},
lines: 1,
- logText: "reply lost: 403",
+ logText: "<3>reply lost: 403",
},
}
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.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()
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)
}
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))
}
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
"context"
"errors"
"fmt"
- "log"
+ "log/slog"
"path/filepath"
"sync"
"time"
// 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
runs *SubagentRuns
layout *ViewLayout
clock func() time.Time
- logger *log.Logger
+ logger *slog.Logger
notify func(Event)
wake chan struct{}
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{
import (
"context"
"encoding/json"
- "log"
"net/http"
"path/filepath"
"strings"
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")
}
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())
"context"
"errors"
"fmt"
- "log"
+ "log/slog"
"net/url"
"os"
"path/filepath"
// 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,
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
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 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.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.")
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 {
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 + ".")
var notice, line string
+ level := slog.LevelInfo
+
+ var attrs []any
+
w.mutex.Lock()
switch event := event.(type) {
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
case *events.Disconnected:
connected := w.connected
if w.startOutage() {
+ level = slog.LevelWarn
line = "disconnected, retrying"
if !connected {
line = "first connect failed, retrying"
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()))
}
}
w.mutex.Unlock()
if line != "" {
- w.logger.Print(line)
+ w.logger.Log(context.Background(), level, line, attrs...)
}
if notice != "" {
import (
"context"
"fmt"
- "io"
- "log"
+ "log/slog"
"os"
"path/filepath"
"slices"
}
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() {
}
// 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
import (
"context"
- "log"
+ "log/slog"
"maps"
"sync"
"time"
// 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),
// 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
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()
--- /dev/null
+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)
+}
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())
})
}
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())
})
}
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())
})
}
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)
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)
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)
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)
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))
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)
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))
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]")
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) {
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) {
projects / onechat / commitdiff