X-Git-Url: https://git.giacomolli.uk/onechat/blobdiff_plain/087d725b5ab41ad34ffd24938482d45a8b99a080..2ad578a24f252706976cddb41bee6cc969f251cd:/telegram_test.go?ds=sidebyside

diff --git a/telegram_test.go b/telegram_test.go
index e360045..60e9e86 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,16 @@ 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")
+
+	// 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)
 }
 
@@ -292,8 +299,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)
 }
@@ -322,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)
@@ -375,7 +383,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",
@@ -384,7 +392,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",
@@ -392,7 +400,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",
@@ -400,7 +408,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",
@@ -408,7 +416,7 @@ func TestRichMessageFailures(t *testing.T) {
 			always:  true,
 			methods: []string{"sendRichMessage"},
 			lines:   1,
-			logText: "reply lost: 403",
+			logText: "<3>reply lost: 403",
 		},
 	}
 
@@ -433,6 +441,7 @@ func TestRichMessageFailures(t *testing.T) {
 			})
 
 			var methods []string
+
 			for _, call := range telegram.Calls() {
 				methods = append(methods, call.method)
 			}
@@ -441,6 +450,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")
 
@@ -551,6 +565,7 @@ func TestRefusedRichPartGoesWithTheTextAsWritten(t *testing.T) {
 	})
 
 	var fallback, rich []string
+
 	for _, call := range telegram.Calls() {
 		switch {
 		case !call.ok:
@@ -595,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(), "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()
@@ -608,7 +639,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)
 }
@@ -640,10 +671,11 @@ func TestBotLogsAnOutageOnlyAtItsStartAndEnd(t *testing.T) {
 	})
 
 	telegramWaitForSent(t, telegram, "ok")
+
 	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))
 }
@@ -880,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