return fmt.Errorf("unknown request %q", request.Type)
}
}
+
+// 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()
+}
// makes Telegram send the update again, and the message repeats once.
//
// A failed Bot API call waits and tries again, from minWait up to maxWait, or
-// as long as the Bot API asks. It never stops the agent.
+// as long as the Bot API asks. It never stops the agent. A TelegramOutage logs
+// the first failure and the end of each run of failures, and the retries
+// between them log nothing.
type TelegramBot struct {
api *TelegramAPI
owner int64
return err
}
+ outage := &TelegramOutage{
+ logger: b.logger,
+ loss: "cannot get messages from Telegram",
+ back: "messages from Telegram come again",
+ }
+
wait := b.minWait
for ctx.Err() == nil {
updates, err := b.api.GetUpdates(ctx, offset)
if err != nil {
_, asked := telegramRetryable(err)
- wait = b.pause(ctx, err, wait, asked)
+ wait = b.pause(ctx, outage, err, wait, asked)
continue
}
+ outage.End()
wait = b.minWait
for _, update := range updates {
if ctx.Err() != nil {
}
}
-// pause logs err and waits the longer of wait and asked, or until ctx ends. It
-// returns the wait of the next failure: twice wait, up to maxWait.
-func (b *TelegramBot) pause(ctx context.Context, err error, wait, asked time.Duration) time.Duration {
+// pause gives err to outage and waits the longer of wait and asked, or until
+// ctx ends. It returns the wait of the next failure: twice wait, up to maxWait.
+func (b *TelegramBot) pause(ctx context.Context, outage *TelegramOutage, err error, wait, asked time.Duration) time.Duration {
delay := max(wait, asked)
- b.logger.Printf("%v (next try in %s)", err, delay)
+ outage.Fail(err, delay)
timer := time.NewTimer(delay)
defer timer.Stop()
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("update ignored: not a message of the owner in the private chat")
+ b.logger.Print("a Telegram message is ignored, because it is not from the owner in the private chat")
return nil
}
// reply is not lost to a bad entity. It tries again after each failure that a
// later try can fix, until ctx ends. It drops the part after any other failure.
func (b *TelegramBot) deliver(ctx context.Context, part TelegramPart) {
+ outage := b.sendOutage()
wait := b.minWait
for {
err := b.api.SendMessage(ctx, b.owner, part.text, part.entities)
+ retry, asked := telegramRetryable(err)
+ if !retry {
+ outage.End()
+ }
+
if err == nil || ctx.Err() != nil {
return
}
var answer *TelegramError
if len(part.entities) > 0 && errors.As(err, &answer) && answer.Status == http.StatusBadRequest {
- b.logger.Printf("entities refused, the message goes again as plain text: %v", err)
+ b.logger.Printf("a reply goes as plain text, because Telegram refused its formatting: %v", err)
part.entities = nil
continue
}
- retry, asked := telegramRetryable(err)
if !retry {
- b.logger.Printf("message dropped: %v", err)
+ b.logger.Printf("a reply to Telegram is lost: %v", err)
return
}
- wait = b.pause(ctx, err, wait, asked)
+ wait = b.pause(ctx, outage, err, wait, asked)
}
}
// the model wrote it. It tries again after each failure that a later try can
// fix, until ctx ends. It drops the message after any other failure.
func (b *TelegramBot) deliverRich(ctx context.Context, markdown string) {
+ outage := b.sendOutage()
wait := b.minWait
for {
err := b.api.SendRichMessage(ctx, b.owner, markdown)
+ retry, asked := telegramRetryable(err)
+ if !retry {
+ outage.End()
+ }
+
if err == nil || ctx.Err() != nil {
return
}
if telegramRejected(err) {
- b.logger.Printf("rich message refused, the reply goes with entities: %v", err)
+ b.logger.Printf("a reply goes with simpler formatting, because Telegram refused its full formatting: %v", err)
for _, part := range telegramReplyParts(telegramUnescapeTags(markdown)) {
b.deliver(ctx, part)
}
return
}
- retry, asked := telegramRetryable(err)
if !retry {
- b.logger.Printf("message dropped: %v", err)
+ b.logger.Printf("a reply to Telegram is lost: %v", err)
return
}
- wait = b.pause(ctx, err, wait, asked)
+ wait = b.pause(ctx, outage, err, wait, asked)
+ }
+}
+
+// sendOutage returns a new outage of the messages to the chat.
+func (b *TelegramBot) sendOutage() *TelegramOutage {
+ return &TelegramOutage{
+ logger: b.logger,
+ loss: "cannot send replies to Telegram",
+ back: "replies go to Telegram again",
}
}
})
}
+// TelegramOutage is one run of failures of a kind of Bot API call. The first
+// failure logs loss, its cause, and the wait of the next try. The retries log
+// 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
+ loss string
+ back string
+ start time.Time
+}
+
+// Fail logs the start of an outage with err and delay, unless an outage runs.
+func (o *TelegramOutage) Fail(err error, delay time.Duration) {
+ if !o.start.IsZero() {
+ return
+ }
+
+ o.start = time.Now()
+ o.logger.Printf("%s: %v (next try in %s)", o.loss, err, durationText(delay))
+}
+
+// End logs the end of the outage that runs, with its length.
+func (o *TelegramOutage) End() {
+ if o.start.IsZero() {
+ return
+ }
+
+ o.logger.Printf("%s, after %s", o.back, durationText(time.Since(o.start)))
+ o.start = time.Time{}
+}
+
// TelegramPart is the text of one message to the chat, at most
// telegramMessageUnits long, and its entities.
type TelegramPart struct {
// getUpdates call can take before the bot gives it up.
telegramPollSlack = 20 * time.Second
+ // telegramPollTimeout is how long one getUpdates call can take.
+ telegramPollTimeout = telegramPollSeconds*time.Second + telegramPollSlack
+
// telegramSendTimeout is how long a sendMessage, sendRichMessage, or
// sendChatAction call can take. A connection that stops without a
// close, such as after a network change, then fails the call, and the
telegramAnswerBytes = 16 << 20
)
-// errTelegramNetwork tells that a Bot API call got no valid answer, such as
-// after a network error. A later call can work.
-var errTelegramNetwork = errors.New("no valid answer from the Bot API")
-
// newTelegramAPI returns the client of the Bot API at base with token.
func newTelegramAPI(base, token string) *TelegramAPI {
return &TelegramAPI{
// after a network error, HTTP 429, or a server error. It returns the wait that
// the Bot API asks for, or 0.
func telegramRetryable(err error) (bool, time.Duration) {
- if errors.Is(err, errTelegramNetwork) {
+ var network *TelegramNetworkError
+ if errors.As(err, &network) {
return true, 0
}
// and returns them. Telegram forgets each update before offset. Only new
// messages are asked for.
func (b *TelegramAPI) GetUpdates(ctx context.Context, offset int64) ([]TelegramUpdate, error) {
- ctx, cancel := context.WithTimeout(ctx, telegramPollSeconds*time.Second+telegramPollSlack)
- defer cancel()
-
var updates []TelegramUpdate
- err := b.call(ctx, "getUpdates", map[string]any{
+ err := b.call(ctx, telegramPollTimeout, "getUpdates", map[string]any{
"offset": offset,
"timeout": telegramPollSeconds,
"allowed_updates": []string{"message"},
// SendMessage sends text to chat with the format of entities, with no parse
// mode, so the text needs no escaping. With no entities, the text is plain. A
-// call that takes longer than telegramSendTimeout fails with
-// errTelegramNetwork.
+// call that takes longer than telegramSendTimeout fails with a
+// TelegramNetworkError.
func (b *TelegramAPI) SendMessage(ctx context.Context, chat int64, text string, entities []TelegramEntity) error {
- ctx, cancel := context.WithTimeout(ctx, b.sendTimeout)
- defer cancel()
-
params := map[string]any{
"chat_id": chat,
"text": text,
params["entities"] = entities
}
- return b.call(ctx, "sendMessage", params, nil)
+ return b.call(ctx, b.sendTimeout, "sendMessage", params, nil)
}
// SendRichMessage sends markdown to chat as a rich message, which Telegram
// renders itself, tables included. A call that takes longer than
-// telegramSendTimeout fails with errTelegramNetwork.
+// telegramSendTimeout fails with a TelegramNetworkError.
func (b *TelegramAPI) SendRichMessage(ctx context.Context, chat int64, markdown string) error {
- ctx, cancel := context.WithTimeout(ctx, b.sendTimeout)
- defer cancel()
-
- return b.call(ctx, "sendRichMessage", map[string]any{
+ return b.call(ctx, b.sendTimeout, "sendRichMessage", map[string]any{
"chat_id": chat,
"rich_message": map[string]any{
"markdown": markdown,
}
// SendTyping shows the typing action in chat for about five seconds. A call
-// that takes longer than telegramSendTimeout fails with errTelegramNetwork.
+// that takes longer than telegramSendTimeout fails with a TelegramNetworkError.
func (b *TelegramAPI) SendTyping(ctx context.Context, chat int64) error {
- ctx, cancel := context.WithTimeout(ctx, b.sendTimeout)
- defer cancel()
-
- return b.call(ctx, "sendChatAction", map[string]any{
+ return b.call(ctx, b.sendTimeout, "sendChatAction", map[string]any{
"chat_id": chat,
"action": "typing",
}, nil)
}
// call sends one call of method with the JSON params and decodes its result
-// into result, when result is not nil.
-func (b *TelegramAPI) call(ctx context.Context, method string, params, result any) error {
+// into result, when result is not nil. The call can take up to timeout. Its
+// errors tell the cause in plain words, with no method name, so that a log line
+// can say first what the call was for.
+func (b *TelegramAPI) call(ctx context.Context, timeout time.Duration, method string, params, result any) error {
+ ctx, cancel := context.WithTimeout(ctx, timeout)
+ defer cancel()
+
body, err := json.Marshal(params)
if err != nil {
return fmt.Errorf("%s: encode request: %w", method, err)
request.Header.Set("Content-Type", "application/json")
response, err := b.http.Do(request)
if err != nil {
- return fmt.Errorf("%s: %w: %s", method, errTelegramNetwork, b.redact(err))
+ return b.networkError("no answer", err, timeout)
}
data, err := io.ReadAll(io.LimitReader(response.Body, telegramAnswerBytes))
err = errors.Join(err, response.Body.Close())
if err != nil {
- return fmt.Errorf("%s: %w: read answer: %s", method, errTelegramNetwork, b.redact(err))
+ return b.networkError("the answer broke off", err, timeout)
}
var answer TelegramAnswer
err = json.Unmarshal(data, &answer)
if err != nil && response.StatusCode != http.StatusOK {
return &TelegramError{
- Method: method,
Status: response.StatusCode,
Description: http.StatusText(response.StatusCode),
}
}
if err != nil {
- return fmt.Errorf("%s: %w: decode answer: %s", method, errTelegramNetwork, b.redact(err))
+ return b.networkError("the answer is not valid JSON", err, timeout)
}
if !answer.OK {
return &TelegramError{
- Method: method,
Status: response.StatusCode,
Description: b.redact(errors.New(answer.Description)),
RetryAfter: time.Duration(answer.Parameters.RetryAfter) * time.Second,
err = json.Unmarshal(answer.Result, result)
if err != nil {
- return fmt.Errorf("%s: %w: decode result: %s", method, errTelegramNetwork, b.redact(err))
+ return b.networkError("the result is not valid", err, timeout)
}
return nil
}
+// networkError returns the TelegramNetworkError of err, which happened at the
+// step that what names. When the call used all of its time timeout, the cause
+// is "no answer in TIMEOUT", because the Go text of a deadline does not tell
+// how long the wait was.
+func (b *TelegramAPI) networkError(what string, err error, timeout time.Duration) error {
+ if errors.Is(err, context.DeadlineExceeded) {
+ return &TelegramNetworkError{
+ Cause: "no answer in " + timeout.String(),
+ }
+ }
+
+ return &TelegramNetworkError{
+ Cause: what + ": " + b.redact(err),
+ }
+}
+
// redact returns the text of err without a URL and without the token. A
// *url.Error holds the URL of the call, which holds the token, so only its
// cause is kept.
return strings.ReplaceAll(err.Error(), b.token, "TOKEN")
}
-// TelegramError is an answer of the Bot API that tells of a failure. RetryAfter
-// is the wait that the Bot API asks for after HTTP 429. Refused tells that the
-// answer is a Bot API answer with ok false, not a page of a proxy or of a
-// server error.
+// TelegramNetworkError tells that a Bot API call got no valid answer, such as
+// after a network error. A later call can work. Cause tells why in plain words,
+// with no URL and no token.
+type TelegramNetworkError struct {
+ Cause string
+}
+
+func (e *TelegramNetworkError) Error() string {
+ return e.Cause
+}
+
+// TelegramError is an answer of the Bot API that tells of a failure. Its text
+// gives the HTTP status and the description, such as "Telegram answered 502 Bad
+// Gateway". RetryAfter is the wait that the Bot API asks for after HTTP 429.
+// Refused tells that the answer is a Bot API answer with ok false, not a page
+// of a proxy or of a server error.
type TelegramError struct {
- Method string
Status int
Description string
RetryAfter time.Duration
}
func (e *TelegramError) Error() string {
- return fmt.Sprintf("%s: Bot API answered %d: %s", e.Method, e.Status, e.Description)
+ return fmt.Sprintf("Telegram answered %d %s", e.Status, e.Description)
}
// TelegramUpdate is one update of getUpdates. Message is nil for the kinds of
api.sendTimeout = 50 * time.Millisecond
start := time.Now()
err := tc.send(t.Context(), api)
- require.ErrorIs(t, err, errTelegramNetwork)
+ require.EqualError(t, err, "no answer in 50ms")
require.Less(t, time.Since(start), 5*time.Second)
require.NotContains(t, err.Error(), telegramTestToken)
require.NotContains(t, err.Error(), server.URL)
}
},
retry: true,
- errorText: "no valid answer",
+ errorText: "no answer",
},
{
name: "rate limit waits as asked",
_, _ = io.WriteString(w, "<html>bad gateway</html>")
},
retry: true,
- errorText: "answered 502: Bad Gateway",
+ errorText: "Telegram answered 502 Bad Gateway",
},
{
name: "token echoed in a description is hidden",
},
retry: false,
rejected: true,
- errorText: "answered 400: Bad Request: can't parse",
+ errorText: "answered 400 Bad Request: can't parse",
},
{
name: "unknown method is a refusal",
},
retry: false,
rejected: true,
- errorText: "answered 404: Not Found",
+ errorText: "answered 404 Not Found",
},
{
name: "not found page of a proxy is not a refusal",
_, _ = io.WriteString(w, "<html>not found</html>")
},
retry: false,
- errorText: "answered 404: Not Found",
+ errorText: "answered 404 Not Found",
},
{
name: "broken answer is retried",
_, _ = io.WriteString(w, `{"ok":`)
},
retry: true,
- errorText: "decode answer",
+ errorText: "not valid JSON",
},
}
server.Close()
_, err := newTelegramAPI(server.URL, telegramTestToken).GetUpdates(t.Context(), 0)
- require.ErrorIs(t, err, errTelegramNetwork)
+ require.ErrorAs(t, err, new(*TelegramNetworkError))
require.NotContains(t, err.Error(), telegramTestToken)
}
"os"
"path/filepath"
"slices"
+ "strconv"
"strings"
"testing"
"time"
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(), "a Telegram message is ignored")
}
func TestBotAnswersThatOnlyTextIsSupported(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(), "cannot send replies to Telegram: no answer in 50ms (next try in 1ms)\n")
+ require.Contains(t, logs.String(), "replies go to Telegram again, after ")
+ require.Equal(t, 2, strings.Count(logs.String(), "\n"))
require.NotContains(t, logs.String(), telegramTestToken)
}
always bool
methods []string
sent []string
+ lines int
logText string
}{
{
always: true,
methods: []string{"sendRichMessage", "sendMessage"},
sent: []string{"a secret word"},
- logText: "rich message refused",
+ lines: 1,
+ logText: "Telegram refused its full formatting",
},
{
name: "unknown method sends the reply once with entities",
always: true,
methods: []string{"sendRichMessage", "sendMessage"},
sent: []string{"a secret word"},
- logText: "rich message refused",
+ lines: 1,
+ logText: "Telegram refused its full 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: "cannot send replies to Telegram: Telegram answered 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: "cannot send replies to Telegram: Telegram answered 500",
},
{
name: "other refusal drops the reply",
status: http.StatusForbidden,
always: true,
methods: []string{"sendRichMessage"},
- logText: "message dropped",
+ lines: 1,
+ logText: "a reply to Telegram is lost: Telegram answered 403",
},
}
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)
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(), "entities refused")
+ require.Contains(t, logs.String(), "a reply goes as plain text, because Telegram refused its formatting")
require.NotContains(t, logs.String(), telegramTestToken)
require.NotContains(t, logs.String(), "secret word")
}
daemonStartTestWithBot(t, newModelFake(t), bot)
require.Eventually(t, func() bool {
- return strings.Count(logs.String(), "no valid answer") >= 2
+ return strings.Contains(logs.String(), "cannot get messages from Telegram: 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, call 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, "cannot get messages from Telegram: Telegram answered 502 Bad Gateway (next try in 1ms)", lines[0])
+ require.Regexp(t, `^messages from Telegram come again, 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
projects / onechat / commitdiff