X-Git-Url: https://git.giacomolli.uk/onechat/blobdiff_plain/5bb22ac2fc501bad7327c119f1d3ac514e3d5398..77f29e78734dc16cfcea5f41b8e0185f8b33534a:/telegram_test.go?ds=sidebyside diff --git a/telegram_test.go b/telegram_test.go index 81e6e18..60e9e86 100644 --- a/telegram_test.go +++ b/telegram_test.go @@ -1,11 +1,11 @@ package main import ( - "log" "net/http" "os" "path/filepath" "slices" + "strconv" "strings" "testing" "time" @@ -15,7 +15,7 @@ import ( func TestOwnerTalksToTheAgentThroughTelegram(t *testing.T) { server := newModelFake(t) - server.reply = func(w http.ResponseWriter, call ModelFakeCall) { + server.reply = func(w http.ResponseWriter, _ ModelFakeCall) { modelWriteEvents(w, modelCompletedEvent([]any{modelMessageItem("Hello from the agent.")}, 100, 0, 5)) } @@ -75,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(), "update ignored") + require.Contains(t, logs.String(), "<6>message ignored") } func TestBotAnswersThatOnlyTextIsSupported(t *testing.T) { @@ -99,7 +99,7 @@ func TestStopFromTelegramInterruptsTheTurn(t *testing.T) { close(release) }) - server.reply = func(w http.ResponseWriter, call ModelFakeCall) { + server.reply = func(_ http.ResponseWriter, _ ModelFakeCall) { close(arrived) <-release } @@ -127,11 +127,79 @@ func TestStopFromTelegramInterruptsTheTurn(t *testing.T) { }) telegramWaitForSent(t, telegram, "Error: interrupted", "No turn runs.") + + telegram.Add(TelegramUpdate{ + UpdateID: 4, + Message: telegramOwnerMessage(stopCommand + " BlueFox"), + }) + + telegramWaitForSent(t, telegram, "No turn runs.", "No subagent BlueFox runs.") } -func TestBotStartsAtTheStoredOffset(t *testing.T) { +func TestBotShowsOnlyTheStartAndTheEndOfASubagent(t *testing.T) { + telegram := newTelegramFake(t) server := newModelFake(t) server.reply = func(w http.ResponseWriter, call ModelFakeCall) { + last := subagentTestLastItem(call) + switch { + case subagentTestCall(call): + // The report comes after the reply of the turn of the spawn. + require.Eventually(t, func() bool { + return slices.Contains(telegram.Sent(), "Started.") + }, 10*time.Second, time.Millisecond) + modelWriteEvents(w, modelCompletedEvent([]any{modelMessageItem("There are 3 files.")}, 100, 0, 5)) + case last["type"] == "function_call_output": + modelWriteEvents(w, modelCompletedEvent([]any{modelMessageItem("Started.")}, 100, 0, 5)) + case strings.HasPrefix(subagentTestText(last), "["): + modelWriteEvents(w, modelCompletedEvent([]any{modelMessageItem("It counted 3 files.")}, 100, 0, 5)) + default: + modelWriteEvents(w, modelCompletedEvent([]any{modelFunctionCallItem("fc_1", "call_1", "spawn", `{"tasks":["Count the files."],"effort":null}`)}, 100, 0, 5)) + } + } + + bot, _ := telegramStartTestBot(t, telegram) + daemonStartTestWithBot(t, server, bot) + telegram.Add(TelegramUpdate{ + UpdateID: 1, + Message: telegramOwnerMessage("Count the files in a subagent."), + }) + + require.Eventually(t, func() bool { + return slices.Contains(telegram.Sent(), "It counted 3 files.") + }, 10*time.Second, time.Millisecond) + + sent := telegram.Sent() + name := strings.TrimSuffix(strings.TrimPrefix(sent[0], "["), "] started") + require.True(t, subagentNameValid(name), sent[0]) + require.Equal(t, []string{ + "[" + name + "] started", + "Started.", + "[" + name + "] finished", + "It counted 3 files.", + }, sent) +} + +func TestBotSkipsTheWorkOfWhatsAppAndTheSchedules(t *testing.T) { + bot := &TelegramBot{ + ready: make(chan struct{}, 1), + } + + bot.Notify(Event{ + Kind: "work", + Source: whatsappSource, + Text: "[WhatsApp] Ana Souza", + }) + bot.Notify(Event{ + Kind: "work", + Source: scheduleSource, + Text: "[Schedule 1] Sunday 2026-11-08 20:05 -03:00, once", + }) + require.Empty(t, bot.queue) +} + +func TestBotStartsAtTheStoredOffset(t *testing.T) { + server := newModelFake(t) + server.reply = func(w http.ResponseWriter, _ ModelFakeCall) { modelWriteEvents(w, modelCompletedEvent([]any{modelMessageItem("ok")}, 100, 0, 5)) } @@ -154,7 +222,7 @@ func TestBotStartsAtTheStoredOffset(t *testing.T) { terminal.WaitFor(t, "[connected to OneChat]") telegramWaitForSent(t, telegram, "ok") - require.Equal(t, float64(10), telegram.Calls()[0].params["offset"]) + require.InDelta(t, float64(10), telegram.Calls()[0].params["offset"], 0) require.NotContains(t, terminal.Output(), "handled before the restart") require.Eventually(t, func() bool { @@ -165,7 +233,7 @@ func TestBotStartsAtTheStoredOffset(t *testing.T) { func TestBotTriesAgainAfterFailures(t *testing.T) { server := newModelFake(t) - server.reply = func(w http.ResponseWriter, call ModelFakeCall) { + server.reply = func(w http.ResponseWriter, _ ModelFakeCall) { modelWriteEvents(w, modelCompletedEvent([]any{modelMessageItem("ok")}, 100, 0, 5)) } @@ -197,8 +265,16 @@ func TestBotTriesAgainAfterFailures(t *testing.T) { }) telegramWaitForSent(t, telegram, "ok") - require.Contains(t, logs.String(), "answered 502") - require.Contains(t, logs.String(), "answered 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") + + // The bot logs the end of the outage after the send returns, so the line + // can come after the fake server has the message. + require.Eventually(t, func() bool { + return strings.Contains(logs.String(), "<6>send back after=") + }, 10*time.Second, time.Millisecond) + require.NotContains(t, logs.String(), telegramTestToken) } @@ -223,14 +299,16 @@ func TestDeliverTriesAgainAfterATimeout(t *testing.T) { require.Equal(t, []string{"hello"}, telegram.Sent()) require.Len(t, telegram.Calls(), 2) - require.Contains(t, logs.String(), "no valid answer") + 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) } func TestRepliesGoAsRichMessages(t *testing.T) { reply := "**Done.** The table:\n\n| Name | Size |\n|:-----|-----:|\n| `a.go` | 10 |\n\n- one\n- two\n\n```go\nx := 1\n```" server := newModelFake(t) - server.reply = func(w http.ResponseWriter, call ModelFakeCall) { + server.reply = func(w http.ResponseWriter, _ ModelFakeCall) { modelWriteEvents(w, modelCompletedEvent([]any{modelMessageItem(reply)}, 100, 0, 5)) } @@ -251,6 +329,7 @@ func TestRepliesGoAsRichMessages(t *testing.T) { telegramWaitForSent(t, telegram, telegramTextOnly) var sends []TelegramFakeCall + for _, call := range telegram.Calls() { if call.method == "sendMessage" || call.method == "sendRichMessage" { sends = append(sends, call) @@ -294,6 +373,7 @@ func TestRichMessageFailures(t *testing.T) { always bool methods []string sent []string + lines int logText string }{ { @@ -302,7 +382,8 @@ func TestRichMessageFailures(t *testing.T) { always: true, methods: []string{"sendRichMessage", "sendMessage"}, sent: []string{"a secret word"}, - logText: "rich message refused", + lines: 1, + logText: "<4>reply sent with simple formatting", }, { name: "unknown method sends the reply once with entities", @@ -310,28 +391,32 @@ func TestRichMessageFailures(t *testing.T) { always: true, methods: []string{"sendRichMessage", "sendMessage"}, sent: []string{"a secret word"}, - logText: "rich message refused", + lines: 1, + logText: "<4>reply sent with simple formatting", }, { name: "rate limit tries the rich message again", status: http.StatusTooManyRequests, methods: []string{"sendRichMessage", "sendRichMessage"}, sent: []string{"a **secret** word"}, - logText: "answered 429", + lines: 2, + logText: "<4>send failed retry=1s: 429", }, { name: "server error tries the rich message again", status: http.StatusInternalServerError, methods: []string{"sendRichMessage", "sendRichMessage"}, sent: []string{"a **secret** word"}, - logText: "answered 500", + lines: 2, + logText: "<4>send failed retry=1ms: 500", }, { name: "other refusal drops the reply", status: http.StatusForbidden, always: true, methods: []string{"sendRichMessage"}, - logText: "message dropped", + lines: 1, + logText: "<3>reply lost: 403", }, } @@ -356,14 +441,20 @@ func TestRichMessageFailures(t *testing.T) { }) var methods []string + for _, call := range telegram.Calls() { methods = append(methods, call.method) } require.Equal(t, tc.methods, methods) require.Equal(t, tc.sent, telegram.Sent()) - require.Equal(t, 1, strings.Count(logs.String(), "\n")) + 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") @@ -474,6 +565,7 @@ func TestRefusedRichPartGoesWithTheTextAsWritten(t *testing.T) { }) var fallback, rich []string + for _, call := range telegram.Calls() { switch { case !call.ok: @@ -492,7 +584,7 @@ func TestRefusedRichPartGoesWithTheTextAsWritten(t *testing.T) { require.LessOrEqual(t, telegramUTF16Units(text), telegramMessageUnits) } - require.True(t, reply == strings.Join(fallback, "")+telegramUnescapeTags(rich[0]), "reply is not sent once and whole") + require.Equal(t, reply, strings.Join(fallback, "")+telegramUnescapeTags(rich[0]), "reply is not sent once and whole") } func TestRefusedEntitiesGoAgainAsPlainText(t *testing.T) { @@ -518,11 +610,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(), "entities refused") + 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() @@ -531,11 +639,47 @@ func TestBotLogsNoTokenWhenTheNetworkFails(t *testing.T) { daemonStartTestWithBot(t, newModelFake(t), bot) require.Eventually(t, func() bool { - return strings.Count(logs.String(), "no valid answer") >= 2 + return strings.Contains(logs.String(), "<4>receive failed retry=1ms: no answer: ") }, 10*time.Second, time.Millisecond) require.NotContains(t, logs.String(), telegramTestToken) } +func TestBotLogsAnOutageOnlyAtItsStartAndEnd(t *testing.T) { + server := newModelFake(t) + server.reply = func(w http.ResponseWriter, _ ModelFakeCall) { + modelWriteEvents(w, modelCompletedEvent([]any{modelMessageItem("ok")}, 100, 0, 5)) + } + + telegram := newTelegramFake(t) + failures := 5 + telegram.fail = func(call TelegramFakeCall) (int, string) { + if call.method != "getUpdates" || failures == 0 { + return 0, "" + } + + failures-- + + return http.StatusBadGateway, "Bad Gateway" + } + + bot, logs := telegramStartTestBot(t, telegram) + daemonStartTestWithBot(t, server, bot) + + telegram.Add(TelegramUpdate{ + UpdateID: 1, + Message: telegramOwnerMessage("a secret word"), + }) + + telegramWaitForSent(t, telegram, "ok") + + lines := strings.Split(strings.TrimSuffix(logs.String(), "\n"), "\n") + require.Len(t, lines, 2) + 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)) +} + func TestSplitMessage(t *testing.T) { testCases := []struct { name string @@ -768,7 +912,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