Log image and message sends

Each WhatsApp send logs one line, message sent at info or message send
failed at warning with its safe cause, and an image shown in Telegram
logs image sent. A chat shows as a short hash, the same for received
images and sends, so the log tells chats apart with no phone number,
text, or caption. Before, a successful send left no trace in the
journal.

Issue: 441b3c7

diff --git a/image_show.go b/image_show.go
index 80204c1b3023cb49f6cf11a4b1a518e72681bc5d..004702977287e0fea44b627184b868935c6d6858 100644 (file)
--- a/image_show.go
+++ b/image_show.go
@@ -31,6 +31,8 @@ func (s *ImageShow) Show(ctx context.Context, name, caption string) (string, err
                if err != nil {
                        return "", fmt.Errorf("show Telegram image: %w", err)
                }
+
+               s.bot.logger.Info("image sent")
        }
 
        return imageText([]string{name}, caption) + "\n" + path, nil

diff --git a/image_show_test.go b/image_show_test.go
index 65e422c40bb328c954be8e578ccdced36c9fd48e..8df642af4111008b4b9d7cb2032e6af44c20ff75 100644 (file)
--- a/image_show_test.go
+++ b/image_show_test.go
@@ -38,7 +38,7 @@ func TestImageShowUsesStoredImageForTelegramAndTerminal(t *testing.T) {
        require.Equal(t, "A red point.", calls[0].params["caption"])
        require.Equal(t, name, calls[0].params["photo_name"])
        require.Equal(t, picture, calls[0].params["photo"])
-       require.Empty(t, logs.String())
+       require.Equal(t, "<6>image sent\n", logs.String())
 }
 
 func TestImageShowRefusesUnknownNamesBeforeSending(t *testing.T) {

diff --git a/whatsapp.go b/whatsapp.go
index 57bfab078301a01907a3c6d898421f24c37df814..4950d280319be4ec6e99db7af475126216e685d4 100644 (file)
--- a/whatsapp.go
+++ b/whatsapp.go
@@ -2,6 +2,7 @@ package main
 
 import (
        "context"
+       "crypto/sha256"
        "database/sql"
        "errors"
        "fmt"
@@ -466,7 +467,7 @@ func (w *WhatsApp) Find(ctx context.Context, name string) (string, error) {
 // Send returns the answer of whatsapp_send for text and an optional stored
 // image to chat, with the durable send id that whatsappSend describes.
 func (w *WhatsApp) Send(ctx context.Context, id, chat, text, image string) (string, error) {
-       return whatsappSend(ctx, w.link(), w.groups, w.state, w.inbox.images, w.clock, id, chat, text, image)
+       return whatsappSend(ctx, w.link(), w.groups, w.state, w.inbox.images, w.logger, w.clock, id, chat, text, image)
 }
 
 func (w *WhatsApp) sessionPath() string {
@@ -1144,6 +1145,14 @@ func whatsappOwnIDs(ids ...string) []string {
        return own
 }
 
+// whatsappChatHash returns a short hash of chat for the daemon log, so that a
+// log line can tell chats apart without a phone number.
+func whatsappChatHash(chat types.JID) string {
+       digest := sha256.Sum256([]byte(chat.ToNonAD().String()))
+
+       return fmt.Sprintf("%x", digest[:6])
+}
+
 // whatsappRedact replaces each of the own IDs own in text with OWN.
 func whatsappRedact(own []string, text string) string {
        for _, id := range own {

diff --git a/whatsapp_inbox.go b/whatsapp_inbox.go
index 9d2183e7d5e282a96442f35ba13d0a7cf58ec1a1..cff43c706607576d5ba9a0cfe447adb627a45de1 100644 (file)
--- a/whatsapp_inbox.go
+++ b/whatsapp_inbox.go
@@ -2,7 +2,6 @@ package main
 
 import (
        "context"
-       "crypto/sha256"
        "fmt"
        "log/slog"
        "slices"
@@ -271,9 +270,8 @@ func (i *WhatsAppInbox) imageText(ctx context.Context, link WhatsAppLink, event
        name, err := whatsappImage(ctx, link.client, i.images, event.Message.GetImageMessage())
        if err != nil {
                chat := event.Info.Chat.ToNonAD()
-               digest := sha256.Sum256([]byte(chat.String()))
                redact := append(slices.Clone(link.own), chat.User)
-               i.logger.Error("image receive failed", "chat", fmt.Sprintf("%x", digest[:6]), "err", whatsappRedact(redact, err.Error()))
+               i.logger.Error("image receive failed", "chat", whatsappChatHash(chat), "err", whatsappRedact(redact, err.Error()))
 
                text := "(image not downloaded)"
                if caption != "" {

diff --git a/whatsapp_send.go b/whatsapp_send.go
index b95a82eb6d53a594df8be45dbd2dee181738ac95..d3d3cbce1e362dd99dd75e01fafa4d6b4eb3c05d 100644 (file)
--- a/whatsapp_send.go
+++ b/whatsapp_send.go
@@ -6,6 +6,7 @@ import (
        "encoding/hex"
        "errors"
        "fmt"
+       "log/slog"
        "slices"
        "strings"
        "time"
@@ -39,11 +40,11 @@ const (
 // during the send gives an answer that the result is unknown, and not a second
 // send. A disconnected WhatsApp sends nothing and makes no record. link gives
 // the device, the client, and the own IDs, groups the names of the groups, and
-// state the send records. The clock gives the times of the records and the time
+// state the send records, and logger gets one line for each send. The clock gives the times of the records and the time
 // zone of the answer. Image names are checked before the record is written, and
 // uploads start only after the record is durable. Text-only records keep their
 // text digest.
-func whatsappSend(ctx context.Context, link WhatsAppLink, groups *WhatsAppGroups, state *WhatsAppState, images *ImageStore, clock func() time.Time, id, chat, text, image string) (string, error) {
+func whatsappSend(ctx context.Context, link WhatsAppLink, groups *WhatsAppGroups, state *WhatsAppState, images *ImageStore, logger *slog.Logger, clock func() time.Time, id, chat, text, image string) (string, error) {
        if !link.linked {
                return whatsappNotLinked, nil
        }
@@ -113,7 +114,10 @@ func whatsappSend(ctx context.Context, link WhatsAppLink, groups *WhatsAppGroups
        if err != nil {
                record.State = whatsappFailed
                record.Answer = "The send failed: " + whatsappRedact(link.own, err.Error()) + "."
+               logger.Warn("message send failed", "chat", whatsappChatHash(jid), "image", image != "", "err", whatsappRedact(append(slices.Clone(link.own), jid.User), err.Error()))
        } else {
+               logger.Info("message sent", "chat", whatsappChatHash(jid), "image", image != "")
+
                name := groups.name(ctx, link, jid.String())
                if jid.Server != types.GroupServer {
                        name = whatsappContactName(ctx, link.device, jid, "")

diff --git a/whatsapp_send_test.go b/whatsapp_send_test.go
index 65c2fc6f1993b2877b0c47e1ff756f76e32b6e25..85b7d15b6f82535f2909c950bb1b9f536848c272 100644 (file)
--- a/whatsapp_send_test.go
+++ b/whatsapp_send_test.go
@@ -88,6 +88,37 @@ func TestWhatsAppSendThatFails(t *testing.T) {
        require.Len(t, fake.Sent(), 1)
 }
 
+func TestWhatsAppSendLogsEachSendWithoutTextOrNumbers(t *testing.T) {
+       dir := t.TempDir()
+       whatsappTestSession(t, dir, true)
+
+       whatsapp, fake, logs := whatsappStartTest(t, dir, newTestClock())
+       daemonStartTestWithWhatsApp(t, newModelFake(t), nil, whatsapp)
+       whatsappTestConnect(t, fake)
+
+       name, err := whatsapp.inbox.images.Save(imageTestPNG(t, 4, 3))
+       require.NoError(t, err)
+
+       _, err = whatsapp.Send(t.Context(), "keys", whatsappTestAna.String(), "The keys are under the mat.", "")
+       require.NoError(t, err)
+
+       _, err = whatsapp.Send(t.Context(), "plan", whatsappTestAna.String(), "The plan.", name)
+       require.NoError(t, err)
+
+       fake.sendErr = errors.New("server error for " + whatsappTestNumber)
+       _, err = whatsapp.Send(t.Context(), "late", whatsappTestAna.String(), "Late.", "")
+       require.NoError(t, err)
+
+       chat := whatsappChatHash(whatsappTestAna)
+       require.Contains(t, logs.String(), "<6>message sent chat="+chat+" image=false\n")
+       require.Contains(t, logs.String(), "<6>message sent chat="+chat+" image=true\n")
+       require.Contains(t, logs.String(), "<4>message send failed chat="+chat+" image=false: server error for OWN\n")
+
+       for _, secret := range []string{"keys", "plan", "Late", whatsappTestNumber, whatsappTestAna.User} {
+               require.NotContains(t, logs.String(), secret)
+       }
+}
+
 func TestWhatsAppSendCutByAStop(t *testing.T) {
        whatsapp, fake := whatsappStartTestLinked(t)
        daemonStartTestWithWhatsApp(t, newModelFake(t), nil, whatsapp)
@@ -254,7 +285,7 @@ func TestWhatsAppImageSendUploadsOnceAndKeepsCaption(t *testing.T) {
        require.Equal(t, name, record.Image)
        require.Equal(t, whatsappSent, record.State)
 
-       again, err := whatsappSend(t.Context(), whatsapp.link(), whatsapp.groups, state, whatsapp.inbox.images, whatsapp.clock, "photo", whatsappTestAna.String(), "The plan.", name)
+       again, err := whatsappSend(t.Context(), whatsapp.link(), whatsapp.groups, state, whatsapp.inbox.images, discardLog(), whatsapp.clock, "photo", whatsappTestAna.String(), "The plan.", name)
        require.NoError(t, err)
        require.Contains(t, again, "nothing was sent again")
        require.Len(t, fake.Uploads(), 1)
@@ -409,7 +440,7 @@ func TestTelegramReceivedPhotoCanBeShownAndSentToWhatsApp(t *testing.T) {
        calls := telegram.Calls()
        require.Equal(t, "sendPhoto", calls[len(calls)-1].method)
        require.Equal(t, picture, calls[len(calls)-1].params["photo"])
-       require.Empty(t, logs.String())
+       require.Equal(t, "<6>image sent\n", logs.String())
 }
 
 func TestWhatsAppImageUploadEndsWithItsCallerOrTimeout(t *testing.T) {