Log Telegram outages once in plain words

A Telegram outage logs one line at its start and one at its end, with
its length, and the retries between them log nothing. Each line says
first what the user loses or gets, such as "cannot get messages from
Telegram" or "replies go to Telegram again, after 1m25s", and then the
cause in plain words, such as "no answer in 1m10s" or "Telegram answered
502 Bad Gateway".

The errors of the Bot API client hold no method name and no Go deadline
text, so that the log line can say what the call was for. A refused
format, a dropped reply, and an ignored message use the same plain
words.

Issue: e4acfcb

diff --git a/daemon.go b/daemon.go
index 3a950da5c91af35f2dc622837f45020f0a89f352..f7ed315745ab37033573a0f6dc122cf6abd304ab 100644 (file)
--- a/daemon.go
+++ b/daemon.go
@@ -420,3 +420,13 @@ func daemonRunRequest(l *TurnLoop, whatsapp *WhatsApp, request SocketRequest, an
                return fmt.Errorf("unknown request %q", request.Type)
        }
 }
                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()
+}

diff --git a/telegram.go b/telegram.go
index e77ea69de90e5a69c3047b6bb2c7a20a5f8273c3..9d7600fd44d89eef4f14340a5fc270208092ea77 100644 (file)
--- a/telegram.go
+++ b/telegram.go
@@ -145,7 +145,9 @@ func (c TelegramConfig) validate() error {
 // 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
 // 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
 type TelegramBot struct {
        api        *TelegramAPI
        owner      int64


@@ -258,6 +260,12 @@ func (b *TelegramBot) poll(ctx context.Context, l *TurnLoop, whatsapp *WhatsApp)
                return err
        }
 
                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)
        wait := b.minWait
        for ctx.Err() == nil {
                updates, err := b.api.GetUpdates(ctx, offset)


@@ -267,11 +275,12 @@ func (b *TelegramBot) poll(ctx context.Context, l *TurnLoop, whatsapp *WhatsApp)
 
                if err != nil {
                        _, asked := telegramRetryable(err)
 
                if err != nil {
                        _, asked := telegramRetryable(err)

-                       wait = b.pause(ctx, err, wait, asked)
+                       wait = b.pause(ctx, outage, err, wait, asked)

 
                        continue
                }
 
 
                        continue
                }
 

+               outage.End()

                wait = b.minWait
                for _, update := range updates {
                        if ctx.Err() != nil {
                wait = b.minWait
                for _, update := range updates {
                        if ctx.Err() != nil {


@@ -335,11 +344,11 @@ func (b *TelegramBot) post(ctx context.Context, event Event) {
        }
 }
 
        }
 }
 

-// 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)
        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()
 
        timer := time.NewTimer(delay)
        defer timer.Stop()


@@ -362,7 +371,7 @@ func (b *TelegramBot) pause(ctx context.Context, err error, wait, asked time.Dur
 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 {
 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
        }
 
                return nil
        }
 


@@ -406,28 +415,33 @@ func (b *TelegramBot) handle(ctx context.Context, l *TurnLoop, whatsapp *WhatsAp
 // 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) {
 // 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)
        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 {
                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
                }
 
                        part.entities = nil
 
                        continue
                }
 

-               retry, asked := telegramRetryable(err)

                if !retry {
                if !retry {

-                       b.logger.Printf("message dropped: %v", err)
+                       b.logger.Printf("a reply to Telegram is lost: %v", err)

                        return
                }
 
                        return
                }
 

-               wait = b.pause(ctx, err, wait, asked)
+               wait = b.pause(ctx, outage, err, wait, asked)

        }
 }
 
        }
 }
 


@@ -439,15 +453,21 @@ func (b *TelegramBot) deliver(ctx context.Context, part TelegramPart) {
 // 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) {
 // 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)
        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) {
                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)
                        }
                        for _, part := range telegramReplyParts(telegramUnescapeTags(markdown)) {
                                b.deliver(ctx, part)
                        }


@@ -455,13 +475,21 @@ func (b *TelegramBot) deliverRich(ctx context.Context, markdown string) {
                        return
                }
 
                        return
                }
 

-               retry, asked := telegramRetryable(err)

                if !retry {
                if !retry {

-                       b.logger.Printf("message dropped: %v", err)
+                       b.logger.Printf("a reply to Telegram is lost: %v", err)

                        return
                }
 
                        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",

        }
 }
 
        }
 }
 


@@ -473,6 +501,37 @@ func (b *TelegramBot) notice(text string) {
        })
 }
 
        })
 }
 

+// 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 {
 // TelegramPart is the text of one message to the chat, at most
 // telegramMessageUnits long, and its entities.
 type TelegramPart struct {

diff --git a/telegram_api.go b/telegram_api.go
index bb4ee2c07bc425eab5805176595def55c22c80c6..24f02ac344954b52f752947f64feeba107c1d7a6 100644 (file)
--- a/telegram_api.go
+++ b/telegram_api.go
@@ -22,6 +22,9 @@ const (
        // getUpdates call can take before the bot gives it up.
        telegramPollSlack = 20 * time.Second
 
        // 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
        // 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


@@ -34,10 +37,6 @@ const (
        telegramAnswerBytes = 16 << 20
 )
 
        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{
 // newTelegramAPI returns the client of the Bot API at base with token.
 func newTelegramAPI(base, token string) *TelegramAPI {
        return &TelegramAPI{


@@ -52,7 +51,8 @@ func newTelegramAPI(base, token string) *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) {
 // 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
        }
 
                return true, 0
        }
 


@@ -88,11 +88,8 @@ type TelegramAPI struct {
 // 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) {
 // 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
        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"},
                "offset":          offset,
                "timeout":         telegramPollSeconds,
                "allowed_updates": []string{"message"},


@@ -103,12 +100,9 @@ func (b *TelegramAPI) GetUpdates(ctx context.Context, offset int64) ([]TelegramU
 
 // 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
 
 // 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 {
 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 := map[string]any{
                "chat_id": chat,
                "text":    text,


@@ -118,17 +112,14 @@ func (b *TelegramAPI) SendMessage(ctx context.Context, chat int64, text string,
                params["entities"] = entities
        }
 
                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
 }
 
 // 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 {
 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,
                "chat_id": chat,
                "rich_message": map[string]any{
                        "markdown": markdown,


@@ -137,20 +128,22 @@ func (b *TelegramAPI) SendRichMessage(ctx context.Context, chat int64, markdown
 }
 
 // SendTyping shows the typing action in chat for about five seconds. A call
 }
 
 // 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 {
 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
                "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)
        body, err := json.Marshal(params)
        if err != nil {
                return fmt.Errorf("%s: encode request: %w", method, err)


@@ -164,32 +157,30 @@ func (b *TelegramAPI) call(ctx context.Context, method string, params, result an
        request.Header.Set("Content-Type", "application/json")
        response, err := b.http.Do(request)
        if err != nil {
        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 {
        }
 
        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{
        }
 
        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 {
                        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{
        }
 
        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,
                        Status:      response.StatusCode,
                        Description: b.redact(errors.New(answer.Description)),
                        RetryAfter:  time.Duration(answer.Parameters.RetryAfter) * time.Second,


@@ -203,12 +194,28 @@ func (b *TelegramAPI) call(ctx context.Context, method string, params, result an
 
        err = json.Unmarshal(answer.Result, result)
        if err != nil {
 
        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
 }
 
        }
 
        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.
 // 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.


@@ -221,12 +228,23 @@ func (b *TelegramAPI) redact(err error) string {
        return strings.ReplaceAll(err.Error(), b.token, "TOKEN")
 }
 
        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 {
 type TelegramError struct {

-       Method      string

        Status      int
        Description string
        RetryAfter  time.Duration
        Status      int
        Description string
        RetryAfter  time.Duration


@@ -234,7 +252,7 @@ type TelegramError struct {
 }
 
 func (e *TelegramError) Error() string {
 }
 
 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
 }
 
 // TelegramUpdate is one update of getUpdates. Message is nil for the kinds of

diff --git a/telegram_api_test.go b/telegram_api_test.go
index 7cdee660314dca0df947d07d02188c8f28c70172..f789101a2bf6a86e15ac226258ef60900fb4c80c 100644 (file)
--- a/telegram_api_test.go
+++ b/telegram_api_test.go
@@ -112,7 +112,7 @@ func TestSendCallsTimeOutOnAStalledConnection(t *testing.T) {
                        api.sendTimeout = 50 * time.Millisecond
                        start := time.Now()
                        err := tc.send(t.Context(), api)
                        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)
                        require.Less(t, time.Since(start), 5*time.Second)
                        require.NotContains(t, err.Error(), telegramTestToken)
                        require.NotContains(t, err.Error(), server.URL)


@@ -149,7 +149,7 @@ func TestBotErrorsDoNotHoldTheToken(t *testing.T) {
                                }
                        },
                        retry:     true,
                                }
                        },
                        retry:     true,

-                       errorText: "no valid answer",
+                       errorText: "no answer",

                },
                {
                        name: "rate limit waits as asked",
                },
                {
                        name: "rate limit waits as asked",


@@ -168,7 +168,7 @@ func TestBotErrorsDoNotHoldTheToken(t *testing.T) {
                                _, _ = io.WriteString(w, "<html>bad gateway</html>")
                        },
                        retry:     true,
                                _, _ = 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",
                },
                {
                        name: "token echoed in a description is hidden",


@@ -187,7 +187,7 @@ func TestBotErrorsDoNotHoldTheToken(t *testing.T) {
                        },
                        retry:     false,
                        rejected:  true,
                        },
                        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",
                },
                {
                        name: "unknown method is a refusal",


@@ -197,7 +197,7 @@ func TestBotErrorsDoNotHoldTheToken(t *testing.T) {
                        },
                        retry:     false,
                        rejected:  true,
                        },
                        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",
                },
                {
                        name: "not found page of a proxy is not a refusal",


@@ -206,7 +206,7 @@ func TestBotErrorsDoNotHoldTheToken(t *testing.T) {
                                _, _ = io.WriteString(w, "<html>not found</html>")
                        },
                        retry:     false,
                                _, _ = io.WriteString(w, "<html>not found</html>")
                        },
                        retry:     false,

-                       errorText: "answered 404: Not Found",
+                       errorText: "answered 404 Not Found",

                },
                {
                        name: "broken answer is retried",
                },
                {
                        name: "broken answer is retried",


@@ -214,7 +214,7 @@ func TestBotErrorsDoNotHoldTheToken(t *testing.T) {
                                _, _ = io.WriteString(w, `{"ok":`)
                        },
                        retry:     true,
                                _, _ = io.WriteString(w, `{"ok":`)
                        },
                        retry:     true,

-                       errorText: "decode answer",
+                       errorText: "not valid JSON",

                },
        }
 
                },
        }
 


@@ -241,6 +241,6 @@ func TestBotErrorsDoNotHoldTheToken(t *testing.T) {
        server.Close()
 
        _, err := newTelegramAPI(server.URL, telegramTestToken).GetUpdates(t.Context(), 0)
        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)
 }
        require.NotContains(t, err.Error(), telegramTestToken)
 }

diff --git a/telegram_test.go b/telegram_test.go
index 66a5f4749d1d17866731412dc8969c8784891792..4d2a9e64feb9bbe48665253365858a1082bf36db 100644 (file)
--- a/telegram_test.go
+++ b/telegram_test.go
@@ -6,6 +6,7 @@ import (
        "os"
        "path/filepath"
        "slices"
        "os"
        "path/filepath"
        "slices"

+       "strconv"

        "strings"
        "testing"
        "time"
        "strings"
        "testing"
        "time"


@@ -75,7 +76,7 @@ func TestBotIgnoresEveryoneButTheOwner(t *testing.T) {
        require.Empty(t, telegram.Sent())
        require.NotContains(t, terminal.Output(), "secret")
        require.NotContains(t, logs.String(), "secret")
        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) {
 }
 
 func TestBotAnswersThatOnlyTextIsSupported(t *testing.T) {


@@ -291,7 +292,9 @@ func TestDeliverTriesAgainAfterATimeout(t *testing.T) {
 
        require.Equal(t, []string{"hello"}, telegram.Sent())
        require.Len(t, telegram.Calls(), 2)
 
        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)
 }
 
        require.NotContains(t, logs.String(), telegramTestToken)
 }
 


@@ -362,6 +365,7 @@ func TestRichMessageFailures(t *testing.T) {
                always  bool
                methods []string
                sent    []string
                always  bool
                methods []string
                sent    []string

+               lines   int

                logText string
        }{
                {
                logText string
        }{
                {


@@ -370,7 +374,8 @@ func TestRichMessageFailures(t *testing.T) {
                        always:  true,
                        methods: []string{"sendRichMessage", "sendMessage"},
                        sent:    []string{"a secret word"},
                        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",
                },
                {
                        name:    "unknown method sends the reply once with entities",


@@ -378,28 +383,32 @@ func TestRichMessageFailures(t *testing.T) {
                        always:  true,
                        methods: []string{"sendRichMessage", "sendMessage"},
                        sent:    []string{"a secret word"},
                        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"},
                },
                {
                        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"},
                },
                {
                        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"},
                },
                {
                        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",

                },
        }
 
                },
        }
 


@@ -430,7 +439,7 @@ func TestRichMessageFailures(t *testing.T) {
 
                        require.Equal(t, tc.methods, methods)
                        require.Equal(t, tc.sent, telegram.Sent())
 
                        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.Contains(t, logs.String(), tc.logText)
                        require.NotContains(t, logs.String(), telegramTestToken)
                        require.NotContains(t, logs.String(), "secret word")


@@ -586,7 +595,7 @@ 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.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")
 }
        require.NotContains(t, logs.String(), telegramTestToken)
        require.NotContains(t, logs.String(), "secret word")
 }


@@ -599,11 +608,46 @@ func TestBotLogsNoTokenWhenTheNetworkFails(t *testing.T) {
        daemonStartTestWithBot(t, newModelFake(t), bot)
 
        require.Eventually(t, func() bool {
        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)
 }
 
        }, 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
 func TestSplitMessage(t *testing.T) {
        testCases := []struct {
                name  string