X-Git-Url: https://git.giacomolli.uk/onechat/blobdiff_plain/eeb821ff17ad79c87ca9b64cd9be26f8612f4a03..12bd9e96f3b3e67290484e3829461e054110db27:/telegram_test.go?ds=sidebyside diff --git a/telegram_test.go b/telegram_test.go index 5e50ec1..dee692d 100644 --- a/telegram_test.go +++ b/telegram_test.go @@ -1,13 +1,15 @@ package main import ( - "log" + "context" "net/http" "os" "path/filepath" "slices" + "strconv" "strings" "testing" + "testing/synctest" "time" "github.com/stretchr/testify/require" @@ -15,7 +17,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 +77,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 +101,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 } @@ -143,7 +145,8 @@ func TestBotShowsOnlyTheStartAndTheEndOfASubagent(t *testing.T) { last := subagentTestLastItem(call) switch { case subagentTestCall(call): - // The report comes after the reply of the turn of the spawn. + // 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) @@ -179,9 +182,27 @@ func TestBotShowsOnlyTheStartAndTheEndOfASubagent(t *testing.T) { }, 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, call ModelFakeCall) { + server.reply = func(w http.ResponseWriter, _ ModelFakeCall) { modelWriteEvents(w, modelCompletedEvent([]any{modelMessageItem("ok")}, 100, 0, 5)) } @@ -204,7 +225,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 { @@ -215,7 +236,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)) } @@ -247,40 +268,52 @@ 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=1s: 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) } func TestDeliverTriesAgainAfterATimeout(t *testing.T) { - telegram := newTelegramFake(t) - stalls := 1 - telegram.stall = func(call TelegramFakeCall) bool { - if call.method != "sendMessage" || stalls == 0 { - return false - } + synctest.Test(t, func(t *testing.T) { + telegram := newTelegramLocalFake(t) + stalls := 1 + telegram.stall = func(call TelegramFakeCall) bool { + if call.method != "sendMessage" || stalls == 0 { + return false + } - stalls-- + stalls-- - return true - } + return true + } - bot, logs := telegramStartTestBot(t, telegram) - bot.api.sendTimeout = 50 * time.Millisecond - bot.deliver(t.Context(), TelegramPart{ - text: "hello", - }) + bot, logs := telegramStartTestBot(t, telegram) + bot.api.http.Transport = telegram + bot.deliver(t.Context(), TelegramPart{ + text: "hello", + }) - require.Equal(t, []string{"hello"}, telegram.Sent()) - require.Len(t, telegram.Calls(), 2) - require.Contains(t, logs.String(), "no valid answer") - require.NotContains(t, logs.String(), telegramTestToken) + require.Equal(t, []string{"hello"}, telegram.Sent()) + require.Len(t, telegram.Calls(), 2) + require.Contains(t, logs.String(), "<4>send failed retry=1s: no answer in 30s\n") + require.Contains(t, logs.String(), "<6>send back after=1s\n") + 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)) } @@ -301,6 +334,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) @@ -344,6 +378,7 @@ func TestRichMessageFailures(t *testing.T) { always bool methods []string sent []string + lines int logText string }{ { @@ -352,7 +387,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", @@ -360,28 +396,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=1s: 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", }, } @@ -406,14 +446,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") @@ -524,6 +570,7 @@ func TestRefusedRichPartGoesWithTheTextAsWritten(t *testing.T) { }) var fallback, rich []string + for _, call := range telegram.Calls() { switch { case !call.ok: @@ -542,7 +589,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) { @@ -568,11 +615,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() @@ -581,11 +644,63 @@ 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=1s: no answer: ") }, 10*time.Second, time.Millisecond) require.NotContains(t, logs.String(), telegramTestToken) } +func TestBotLogsAnOutageOnlyAtItsStartAndEnd(t *testing.T) { + synctest.Test(t, func(t *testing.T) { + telegram := newTelegramLocalFake(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) + bot.api.http.Transport = telegram + whatsapp, _, _ := whatsappStartTest(t, t.TempDir(), newTestClock()) + loop, _ := newTestIdleTurnLoop(t, whatsapp) + + telegram.Add(TelegramUpdate{ + UpdateID: 1, + Message: telegramOwnerMessage("a secret word"), + }) + + ctx, cancel := context.WithCancel(t.Context()) + defer cancel() + + done := make(chan error, 1) + go func() { + done <- bot.poll(ctx, loop, whatsapp) + }() + + time.Sleep(31 * time.Second) + synctest.Wait() + require.Equal(t, 1, loop.memory.Len()) + + message, err := loop.memory.Message(0) + require.NoError(t, err) + require.Equal(t, "a secret word", message.Text) + + lines := strings.Split(strings.TrimSuffix(logs.String(), "\n"), "\n") + require.Equal(t, []string{ + "<4>receive failed retry=1s: 502 Bad Gateway", + "<6>receive back after=31s", + }, lines) + require.NotContains(t, logs.String(), "secret word") + require.NotContains(t, logs.String(), strconv.FormatInt(telegramTestOwner, 10)) + cancel() + require.NoError(t, <-done) + }) +} + func TestSplitMessage(t *testing.T) { testCases := []struct { name string @@ -812,15 +927,12 @@ func TestLoadBotConfig(t *testing.T) { } // telegramStartTestBot returns a bot of telegramTestOwner on server, with its -// offset file in a temporary directory and short waits, and the buffer of its -// log. +// offset file in a temporary directory and the buffer of its log. func telegramStartTestBot(t *testing.T, server *TelegramFake) (*TelegramBot, *SyncBuffer) { t.Helper() logs := &SyncBuffer{} - bot := newTelegramBot(newTelegramAPI(server.URL, telegramTestToken), telegramTestOwner, filepath.Join(t.TempDir(), telegramOffsetFileName), log.New(logs, "", 0)) - bot.minWait = time.Millisecond - bot.maxWait = 10 * time.Millisecond + bot := newTelegramBot(newTelegramAPI(server.URL, telegramTestToken), telegramTestOwner, filepath.Join(t.TempDir(), telegramOffsetFileName), daemonTestLogger(logs)) return bot, logs }