X-Git-Url: https://git.giacomolli.uk/onechat/blobdiff_plain/d008b46cbfc6348255e9b9a1fc009f0e4bd6aa2a..2124c559da8f164a43a3da987b399b6ac6125035:/telegram_test.go?ds=sidebyside diff --git a/telegram_test.go b/telegram_test.go index 66a5f47..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 } @@ -199,7 +199,7 @@ func TestBotSkipsTheWorkOfWhatsAppAndTheSchedules(t *testing.T) { 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)) } @@ -222,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 { @@ -233,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)) } @@ -265,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) } @@ -291,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)) } @@ -319,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) @@ -362,6 +373,7 @@ func TestRichMessageFailures(t *testing.T) { always bool methods []string sent []string + lines int logText string }{ { @@ -370,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", @@ -378,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", }, } @@ -424,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") @@ -542,6 +565,7 @@ func TestRefusedRichPartGoesWithTheTextAsWritten(t *testing.T) { }) var fallback, rich []string + for _, call := range telegram.Calls() { switch { case !call.ok: @@ -560,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) { @@ -586,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() @@ -599,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 @@ -836,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