Log each change of the WhatsApp connection

The WhatsApp log gets one line for each change of the connection of the
linked device: connected, a failed first connection, a lost connection,
connected again with the length of the outage, a connection that does
not come back by itself, a link, an unlink, and a logout from the phone.
The retries of the library between them log nothing, and the logger of
the library stays off.

Each line says first what happens to the WhatsApp messages, and then the
cause. An unlink clears the time of the last disconnection, so the first
connection of a new link does not count as the end of an outage.

Issue: e4acfcb

diff --git a/whatsapp.go b/whatsapp.go
index 75de73f96c57b25fb717bde9189103e5518b3937..2c1b6cb9aaa70e327fd4a342d282fb97ecd4a247 100644 (file)
--- a/whatsapp.go
+++ b/whatsapp.go
@@ -405,7 +405,7 @@ func (w *WhatsApp) connect(ctx context.Context) {
 
        err := client.ConnectContext(ctx)
        if err != nil {
-               w.logger.Printf("connect: %s", w.redact(err.Error()))
+               w.logger.Printf("WhatsApp messages do not come, because the connection failed, and it is tried again only at a restart of the daemon: %s", w.redact(err.Error()))
        }
 }
 
@@ -435,6 +435,7 @@ func (w *WhatsApp) loggedOut(ctx context.Context, l *TurnLoop) error {
                return nil
        }
 
+       w.logger.Print("WhatsApp messages stop, because the phone logged out this device (run /whatsapp pair PHONE to link it again)")
        err := w.inbox.deliver(ctx, l, w.link(), true)
        if err != nil {
                return err
@@ -442,12 +443,12 @@ func (w *WhatsApp) loggedOut(ctx context.Context, l *TurnLoop) error {
 
        err = w.removeSession()
        if err != nil {
-               w.logger.Printf("delete the session after the logout: %v", err)
+               w.logger.Printf("the session of the logged out device stays on the disk, because its delete failed: %v", err)
        }
 
        err = l.note("WhatsApp was unlinked from the phone.")
        if err != nil {
-               w.logger.Printf("note the logout: %v", err)
+               w.logger.Printf("the chat has no note of the logout, because its write failed: %v", err)
        }
 
        w.broadcast("WhatsApp was unlinked from the phone. Run /whatsapp pair PHONE to link it again.")
@@ -490,9 +491,10 @@ func (w *WhatsApp) unlink(ctx context.Context, l *TurnLoop, answer func(text str
                return nil
        }
 
+       w.logger.Print("WhatsApp messages stop, because the user unlinked WhatsApp")
        err = l.note("WhatsApp is unlinked.")
        if err != nil {
-               w.logger.Printf("note the unlink: %v", err)
+               w.logger.Printf("the chat has no note of the unlink, because its write failed: %v", err)
        }
 
        if client == nil || logoutErr != nil {
@@ -514,6 +516,7 @@ func (w *WhatsApp) removeSession() error {
        w.linked = false
        w.own = nil
        w.connected = false
+       w.disconnectedAt = time.Time{}
        if w.timer != nil {
                w.timer.Stop()
        }
@@ -628,10 +631,11 @@ func (w *WhatsApp) pair(ctx, runCtx context.Context, l *TurnLoop, phone string,
                case item.Event == whatsmeow.QRChannelSuccess.Event:
                        linked = true
                        w.linkedBy(client)
+                       w.logger.Print("WhatsApp is linked")
 
                        err = l.note("WhatsApp is linked.")
                        if err != nil {
-                               w.logger.Printf("note the link: %v", err)
+                               w.logger.Printf("the chat has no note of the link, because its write failed: %v", err)
                        }
 
                        answer("WhatsApp is linked to +" + phone + ".")
@@ -694,6 +698,11 @@ func (w *WhatsApp) linkedBy(client WhatsAppClient) {
 // the library tries again. After noticeDelay of a disconnection, all clients
 // get one notice, and they get one more when the connection comes back. A
 // disconnection that the library does not try again gives a notice at once.
+//
+// The log of the daemon gets one line for each change of the connection of the
+// linked device: connected, a failed first connection, a lost connection, and
+// connected again with the length of the outage. The retries of the library
+// between them log nothing.
 func (w *WhatsApp) handle(event any) bool {
        switch event := event.(type) {
        case *events.Message:
@@ -714,12 +723,20 @@ func (w *WhatsApp) handle(event any) bool {
                w.inbox.startCatchup()
        }
 
-       var notice string
+       var notice, line string
        w.mutex.Lock()
        switch event := event.(type) {
        case *events.PairSuccess:
                w.own = whatsappOwnIDs(event.ID.User, event.LID.User)
        case *events.Connected:
+               switch {
+               case !w.linked || w.connected:
+               case w.disconnectedAt.IsZero():
+                       line = "WhatsApp is connected, and new messages come in"
+               default:
+                       line = "WhatsApp is connected again, after " + durationText(w.clock().Sub(w.disconnectedAt))
+               }
+
                w.connected = true
                w.connectedAt = w.clock()
                if w.timer != nil {
@@ -732,6 +749,11 @@ func (w *WhatsApp) handle(event any) bool {
                }
        case *events.Disconnected:
                if w.linked && (w.connected || w.disconnectedAt.IsZero()) {
+                       line = "new WhatsApp messages wait, because the connection is lost (the next try is automatic)"
+                       if !w.connected {
+                               line = "new WhatsApp messages wait, because the first connection failed (the next try is automatic)"
+                       }
+
                        w.disconnectedAt = w.clock()
                        w.disconnections++
                        disconnections := w.disconnections
@@ -751,10 +773,20 @@ func (w *WhatsApp) handle(event any) bool {
                        w.connected = false
                        w.noticed = true
                        notice = "WhatsApp is disconnected and does not connect again by itself: " + event.PermanentDisconnectDescription() + ". Restart the daemon to try again."
+                       line = "WhatsApp messages do not come, because the connection is lost and it is tried again only at a restart of the daemon: " + whatsappRedact(w.own, event.PermanentDisconnectDescription())
                }
        }
+
+       if w.closed {
+               line = ""
+       }
+
        w.mutex.Unlock()
 
+       if line != "" {
+               w.logger.Print(line)
+       }
+
        if notice != "" {
                w.broadcast(notice)
        }

diff --git a/whatsapp_groups.go b/whatsapp_groups.go
index ab5ed61ab769bd0ee66fdf9fff461ff0f44c59c8..e8111c30864e278bcdcfac07c2654c2ce6bc1cba 100644 (file)
--- a/whatsapp_groups.go
+++ b/whatsapp_groups.go
@@ -80,7 +80,7 @@ func (g *WhatsAppGroups) read(ctx context.Context, link WhatsAppLink) bool {
 
        groups, err := link.client.GetJoinedGroups(ctx)
        if err != nil {
-               g.logger.Printf("read the groups: %s", whatsappRedact(link.own, err.Error()))
+               g.logger.Printf("group names can be missing, because the list of groups did not load: %s", whatsappRedact(link.own, err.Error()))
        }
 
        g.mutex.Lock()

diff --git a/whatsapp_test.go b/whatsapp_test.go
index 1ca0a52318d6cf85a8cf141d87773a74013ada0b..5c38d59123714b757bea6d4d330d1672fed0ab60 100644 (file)
--- a/whatsapp_test.go
+++ b/whatsapp_test.go
@@ -37,12 +37,38 @@ func TestWhatsAppStatusFollowsTheConnection(t *testing.T) {
 func TestWhatsAppStatusOfAFirstConnectionThatFailed(t *testing.T) {
        dir := t.TempDir()
        whatsappTestSession(t, dir, true)
-       whatsapp, fake, _ := whatsappStartTest(t, dir, newTestClock())
+       whatsapp, fake, logs := whatsappStartTest(t, dir, newTestClock())
        daemonStartTestWithWhatsApp(t, newModelFake(t), nil, whatsapp)
 
        <-fake.connects
        require.True(t, fake.Emit(&events.Disconnected{}))
        require.Equal(t, "WhatsApp is linked and disconnected since 2026-01-01 12:00.", whatsapp.Status())
+       require.Equal(t, "new WhatsApp messages wait, because the first connection failed (the next try is automatic)\n", logs.String())
+}
+
+func TestWhatsAppLogsEachChangeOfTheConnectionOnce(t *testing.T) {
+       dir := t.TempDir()
+       whatsappTestSession(t, dir, true)
+       clock := newTestClock()
+       whatsapp, fake, logs := whatsappStartTest(t, dir, clock)
+       daemonStartTestWithWhatsApp(t, newModelFake(t), nil, whatsapp)
+
+       <-fake.connects
+       require.True(t, fake.Emit(&events.Connected{}))
+       clock.now = clock.now.Add(time.Minute)
+       require.True(t, fake.Emit(&events.Disconnected{}))
+       clock.now = clock.now.Add(time.Minute)
+       require.True(t, fake.Emit(&events.Disconnected{}))
+       clock.now = clock.now.Add(25 * time.Second)
+       require.True(t, fake.Emit(&events.Connected{}))
+
+       require.Equal(t, []string{
+               "WhatsApp is connected, and new messages come in",
+               "new WhatsApp messages wait, because the connection is lost (the next try is automatic)",
+               "WhatsApp is connected again, after 1m25s",
+       }, strings.Split(strings.TrimSuffix(logs.String(), "\n"), "\n"))
+       require.NotContains(t, logs.String(), whatsappTestNumber)
+       require.NotContains(t, logs.String(), whatsappTestLID)
 }
 
 func TestWhatsAppIsNotLinkedWithoutALinkedDevice(t *testing.T) {
@@ -370,7 +396,7 @@ func TestWhatsAppLogsNoOwnNumber(t *testing.T) {
        require.Eventually(t, func() bool {
                return logs.String() != ""
        }, 10*time.Second, time.Millisecond)
-       require.Equal(t, "connect: no route for OWN@s.whatsapp.net and OWN@lid\n", logs.String())
+       require.Equal(t, "WhatsApp messages do not come, because the connection failed, and it is tried again only at a restart of the daemon: no route for OWN@s.whatsapp.net and OWN@lid\n", logs.String())
 }
 
 func TestWhatsAppPhone(t *testing.T) {