Fetch plugin logs from server (#193)

Co-authored-by: Jesse Hallam <jesse.hallam@gmail.com>

build/pluginctl/logs.go

@@ -0,0 +1,185 @@
+package main
+
+import (
+	"context"
+	"encoding/json"
+	"errors"
+	"fmt"
+	"io"
+	"os"
+	"slices"
+	"strings"
+	"time"
+
+	"github.com/mattermost/mattermost/server/public/model"
+)
+
+const (
+	logsPerPage     = 100 // logsPerPage is the number of log entries to fetch per API call
+	timeStampFormat = "2006-01-02 15:04:05.000 Z07:00"
+)
+
+// logs fetches the latest 500 log entries from Mattermost,
+// and prints only the ones related to the plugin to stdout.
+func logs(ctx context.Context, client *model.Client4, pluginID string) error {
+	err := checkJSONLogsSetting(ctx, client)
+	if err != nil {
+		return err
+	}
+
+	logs, err := fetchLogs(ctx, client, 0, 500, pluginID, time.Unix(0, 0))
+	if err != nil {
+		return fmt.Errorf("failed to fetch log entries: %w", err)
+	}
+
+	err = printLogEntries(logs)
+	if err != nil {
+		return fmt.Errorf("failed to print logs entries: %w", err)
+	}
+
+	return nil
+}
+
+// watchLogs fetches log entries from Mattermost and print them to stdout.
+// It will return without an error when ctx is canceled.
+func watchLogs(ctx context.Context, client *model.Client4, pluginID string) error {
+	err := checkJSONLogsSetting(ctx, client)
+	if err != nil {
+		return err
+	}
+
+	now := time.Now()
+	var oldestEntry string
+
+	ticker := time.NewTicker(1 * time.Second)
+	defer ticker.Stop()
+	for {
+		select {
+		case <-ctx.Done():
+			return nil
+		case <-ticker.C:
+			var page int
+			for {
+				logs, err := fetchLogs(ctx, client, page, logsPerPage, pluginID, now)
+				if err != nil {
+					return fmt.Errorf("failed to fetch log entries: %w", err)
+				}
+
+				var allNew bool
+				logs, oldestEntry, allNew = checkOldestEntry(logs, oldestEntry)
+
+				err = printLogEntries(logs)
+				if err != nil {
+					return fmt.Errorf("failed to print logs entries: %w", err)
+				}
+
+				if !allNew {
+					// No more logs to fetch
+					break
+				}
+				page++
+			}
+		}
+	}
+}
+
+// checkOldestEntry check a if logs contains new log entries.
+// It returns the filtered slice of log entries, the new oldest entry and whether or not all entries were new.
+func checkOldestEntry(logs []string, oldest string) ([]string, string, bool) {
+	if len(logs) == 0 {
+		return nil, oldest, false
+	}
+
+	newOldestEntry := logs[(len(logs) - 1)]
+
+	i := slices.Index(logs, oldest)
+	switch i {
+	case -1:
+		// Every log entry is new
+		return logs, newOldestEntry, true
+	case len(logs) - 1:
+		// No new log entries
+		return nil, oldest, false
+	default:
+		// Filter out oldest log entry
+		return logs[i+1:], newOldestEntry, false
+	}
+}
+
+// fetchLogs fetches log entries from Mattermost
+// and filters them based on pluginID and timestamp.
+func fetchLogs(ctx context.Context, client *model.Client4, page, perPage int, pluginID string, since time.Time) ([]string, error) {
+	logs, _, err := client.GetLogs(ctx, page, perPage)
+	if err != nil {
+		return nil, fmt.Errorf("failed to get logs from Mattermost: %w", err)
+	}
+
+	logs, err = filterLogEntries(logs, pluginID, since)
+	if err != nil {
+		return nil, fmt.Errorf("failed to filter log entries: %w", err)
+	}
+
+	return logs, nil
+}
+
+// filterLogEntries filters a given slice of log entries by pluginID.
+// It also filters out any entries which timestamps are older then since.
+func filterLogEntries(logs []string, pluginID string, since time.Time) ([]string, error) {
+	type logEntry struct {
+		PluginID  string `json:"plugin_id"`
+		Timestamp string `json:"timestamp"`
+	}
+
+	var ret []string
+
+	for _, e := range logs {
+		var le logEntry
+		err := json.Unmarshal([]byte(e), &le)
+		if err != nil {
+			return nil, fmt.Errorf("failed to unmarshal log entry into JSON: %w", err)
+		}
+		if le.PluginID != pluginID {
+			continue
+		}
+
+		let, err := time.Parse(timeStampFormat, le.Timestamp)
+		if err != nil {
+			return nil, fmt.Errorf("unknown timestamp format: %w", err)
+		}
+		if let.Before(since) {
+			continue
+		}
+
+		// Log entries returned by the API have a newline a prefix.
+		// Remove that to make printing consistent.
+		e = strings.TrimPrefix(e, "\n")
+
+		ret = append(ret, e)
+	}
+
+	return ret, nil
+}
+
+// printLogEntries prints a slice of log entries to stdout.
+func printLogEntries(entries []string) error {
+	for _, e := range entries {
+		_, err := io.WriteString(os.Stdout, e+"\n")
+		if err != nil {
+			return fmt.Errorf("failed to write log entry to stdout: %w", err)
+		}
+	}
+
+	return nil
+}
+
+func checkJSONLogsSetting(ctx context.Context, client *model.Client4) error {
+	cfg, _, err := client.GetConfig(ctx)
+	if err != nil {
+		return fmt.Errorf("failed to fetch config: %w", err)
+	}
+	if cfg.LogSettings.FileJson == nil || !*cfg.LogSettings.FileJson {
+		return errors.New("JSON output for file logs are disabled. Please enable LogSettings.FileJson via the configration in Mattermost.") //nolint:revive,stylecheck
+	}
+
+	return nil
+}

build/pluginctl/logs_test.go

@@ -0,0 +1,202 @@
+package main
+
+import (
+	"fmt"
+	"testing"
+	"time"
+)
+
+func TestCheckOldestEntry(t *testing.T) {
+	for name, tc := range map[string]struct {
+		logs           []string
+		oldest         string
+		expectedLogs   []string
+		expectedOldest string
+		expectedAllNew bool
+	}{
+		"nil logs": {
+			logs:           nil,
+			oldest:         "oldest",
+			expectedLogs:   nil,
+			expectedOldest: "oldest",
+			expectedAllNew: false,
+		},
+		"empty logs": {
+			logs:           []string{},
+			oldest:         "oldest",
+			expectedLogs:   nil,
+			expectedOldest: "oldest",
+			expectedAllNew: false,
+		},
+		"no new entries, one old entry": {
+			logs:           []string{"old"},
+			oldest:         "old",
+			expectedLogs:   []string{},
+			expectedOldest: "old",
+			expectedAllNew: false,
+		},
+		"no new entries, multipile old entries": {
+			logs:           []string{"old1", "old2", "old3"},
+			oldest:         "old3",
+			expectedLogs:   []string{},
+			expectedOldest: "old3",
+			expectedAllNew: false,
+		},
+		"one new entry, no old entry": {
+			logs:           []string{"new"},
+			oldest:         "old",
+			expectedLogs:   []string{"new"},
+			expectedOldest: "new",
+			expectedAllNew: true,
+		},
+		"multipile new entries, no old entry": {
+			logs:           []string{"new1", "new2", "new3"},
+			oldest:         "old",
+			expectedLogs:   []string{"new1", "new2", "new3"},
+			expectedOldest: "new3",
+			expectedAllNew: true,
+		},
+		"one new entry, one old entry": {
+			logs:           []string{"old", "new"},
+			oldest:         "old",
+			expectedLogs:   []string{"new"},
+			expectedOldest: "new",
+			expectedAllNew: false,
+		},
+		"one new entry, multipile old entries": {
+			logs:           []string{"old1", "old2", "old3", "new"},
+			oldest:         "old3",
+			expectedLogs:   []string{"new"},
+			expectedOldest: "new",
+			expectedAllNew: false,
+		},
+		"multipile new entries, ultipile old entries": {
+			logs:           []string{"old1", "old2", "old3", "new1", "new2", "new3"},
+			oldest:         "old3",
+			expectedLogs:   []string{"new1", "new2", "new3"},
+			expectedOldest: "new3",
+			expectedAllNew: false,
+		},
+	} {
+		t.Run(name, func(t *testing.T) {
+			logs, oldest, allNew := checkOldestEntry(tc.logs, tc.oldest)
+
+			if allNew != tc.expectedAllNew {
+				t.Logf("expected allNew: %v, got %v", tc.expectedAllNew, allNew)
+				t.Fail()
+			}
+			if oldest != tc.expectedOldest {
+				t.Logf("expected oldest: %v, got %v", tc.expectedOldest, oldest)
+				t.Fail()
+			}
+
+			compareSlice(t, tc.expectedLogs, logs)
+		})
+	}
+}
+
+func TestFilterLogEntries(t *testing.T) {
+	now := time.Now()
+
+	for name, tc := range map[string]struct {
+		logs         []string
+		pluginID     string
+		since        time.Time
+		expectedLogs []string
+		expectedErr  bool
+	}{
+		"nil slice": {
+			logs:         nil,
+			expectedLogs: nil,
+			expectedErr:  false,
+		},
+		"empty slice": {
+			logs:         []string{},
+			expectedLogs: nil,
+			expectedErr:  false,
+		},
+		"no JSON": {
+			logs: []string{
+				`{"foo"`,
+			},
+			expectedLogs: nil,
+			expectedErr:  true,
+		},
+		"unknown time format": {
+			logs: []string{
+				`{"message":"foo", "plugin_id": "some.plugin.id", "timestamp": "2023-12-18 10:58:53"}`,
+			},
+			pluginID:     "some.plugin.id",
+			expectedLogs: nil,
+			expectedErr:  true,
+		},
+		"one matching entry": {
+			logs: []string{
+				`{"message":"foo", "plugin_id": "some.plugin.id", "timestamp": "2023-12-18 10:58:53.091 +01:00"}`,
+			},
+			pluginID: "some.plugin.id",
+			expectedLogs: []string{
+				`{"message":"foo", "plugin_id": "some.plugin.id", "timestamp": "2023-12-18 10:58:53.091 +01:00"}`,
+			},
+			expectedErr: false,
+		},
+		"filter out non plugin entries": {
+			logs: []string{
+				`{"message":"bar1", "timestamp": "2023-12-18 10:58:52.091 +01:00"}`,
+				`{"message":"foo", "plugin_id": "some.plugin.id", "timestamp": "2023-12-18 10:58:53.091 +01:00"}`,
+				`{"message":"bar2", "timestamp": "2023-12-18 10:58:54.091 +01:00"}`,
+			},
+			pluginID: "some.plugin.id",
+			expectedLogs: []string{
+				`{"message":"foo", "plugin_id": "some.plugin.id", "timestamp": "2023-12-18 10:58:53.091 +01:00"}`,
+			},
+			expectedErr: false,
+		},
+		"filter out old entries": {
+			logs: []string{
+				fmt.Sprintf(`{"message":"old2", "plugin_id": "some.plugin.id", "timestamp": "%s"}`, time.Now().Add(-2*time.Second).Format(timeStampFormat)),
+				fmt.Sprintf(`{"message":"old1", "plugin_id": "some.plugin.id", "timestamp": "%s"}`, time.Now().Add(-1*time.Second).Format(timeStampFormat)),
+				fmt.Sprintf(`{"message":"now", "plugin_id": "some.plugin.id", "timestamp": "%s"}`, time.Now().Format(timeStampFormat)),
+				fmt.Sprintf(`{"message":"new1", "plugin_id": "some.plugin.id", "timestamp": "%s"}`, time.Now().Add(1*time.Second).Format(timeStampFormat)),
+				fmt.Sprintf(`{"message":"new2", "plugin_id": "some.plugin.id", "timestamp": "%s"}`, time.Now().Add(2*time.Second).Format(timeStampFormat)),
+			},
+			pluginID: "some.plugin.id",
+			since:    now,
+			expectedLogs: []string{
+				fmt.Sprintf(`{"message":"new1", "plugin_id": "some.plugin.id", "timestamp": "%s"}`, time.Now().Add(1*time.Second).Format(timeStampFormat)),
+				fmt.Sprintf(`{"message":"new2", "plugin_id": "some.plugin.id", "timestamp": "%s"}`, time.Now().Add(2*time.Second).Format(timeStampFormat)),
+			},
+			expectedErr: false,
+		},
+	} {
+		t.Run(name, func(t *testing.T) {
+			logs, err := filterLogEntries(tc.logs, tc.pluginID, tc.since)
+			if tc.expectedErr {
+				if err == nil {
+					t.Logf("expected error, got nil")
+					t.Fail()
+				}
+			} else {
+				if err != nil {
+					t.Logf("expected no error, got %v", err)
+					t.Fail()
+				}
+			}
+			compareSlice(t, tc.expectedLogs, logs)
+		})
+	}
+}
+
+func compareSlice[S ~[]E, E comparable](t *testing.T, expected, got S) {
+	if len(expected) != len(got) {
+		t.Logf("expected len: %v, got %v", len(expected), len(got))
+		t.FailNow()
+	}
+
+	for i := 0; i < len(expected); i++ {
+		if expected[i] != got[i] {
+			t.Logf("expected [%d]: %v, got %v", i, expected[i], got[i])
+			t.Fail()
+		}
+	}
+}

build/pluginctl/main.go

@@ -57,6 +57,10 @@ func pluginctl() error {
 		return enablePlugin(ctx, client, os.Args[2])
 	case "reset":
 		return resetPlugin(ctx, client, os.Args[2])
+	case "logs":
+		return logs(ctx, client, os.Args[2])
+	case "logs-watch":
+		return watchLogs(context.WithoutCancel(ctx), client, os.Args[2]) // Keep watching forever
 	default:
 		return errors.New("invalid second argument")
 	}