From 8dd6e7c187f8c26f8aeb4865e5b2fb3807f4326a Mon Sep 17 00:00:00 2001 From: Ben Schumacher Date: Tue, 30 Jan 2024 16:49:59 +0100 Subject: [PATCH] Fetch plugin logs from server (#193) Co-authored-by: Jesse Hallam --- Makefile | 8 ++ build/pluginctl/logs.go | 185 ++++++++++++++++++++++++++++++++ build/pluginctl/logs_test.go | 202 +++++++++++++++++++++++++++++++++++ build/pluginctl/main.go | 4 + go.mod | 2 +- go.sum | 4 + 6 files changed, 404 insertions(+), 1 deletion(-) create mode 100644 build/pluginctl/logs.go create mode 100644 build/pluginctl/logs_test.go diff --git a/Makefile b/Makefile index 5342f19..dff7546 100644 --- a/Makefile +++ b/Makefile @@ -278,6 +278,14 @@ ifneq ($(HAS_WEBAPP),) endif rm -fr build/bin/ +.PHONY: logs +logs: + ./build/bin/pluginctl logs $(PLUGIN_ID) + +.PHONY: logs-watch +logs-watch: + ./build/bin/pluginctl logs-watch $(PLUGIN_ID) + # Help documentation à la https://marmelab.com/blog/2016/02/29/auto-documented-makefile.html help: @cat Makefile build/*.mk | grep -v '\.PHONY' | grep -v '\help:' | grep -B1 -E '^[a-zA-Z0-9_.-]+:.*' | sed -e "s/:.*//" | sed -e "s/^## //" | grep -v '\-\-' | sed '1!G;h;$$!d' | awk 'NR%2{printf "\033[36m%-30s\033[0m",$$0;next;}1' | sort diff --git a/build/pluginctl/logs.go b/build/pluginctl/logs.go new file mode 100644 index 0000000..f20e8bb --- /dev/null +++ b/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 +} diff --git a/build/pluginctl/logs_test.go b/build/pluginctl/logs_test.go new file mode 100644 index 0000000..687d8c2 --- /dev/null +++ b/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() + } + } +} diff --git a/build/pluginctl/main.go b/build/pluginctl/main.go index 54572fc..2f80af5 100644 --- a/build/pluginctl/main.go +++ b/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") } diff --git a/go.mod b/go.mod index e192a30..3724fd4 100644 --- a/go.mod +++ b/go.mod @@ -1,6 +1,6 @@ module github.com/mattermost/mattermost-plugin-starter-template -go 1.19 +go 1.21 require ( github.com/mattermost/mattermost/server/public v0.0.6 diff --git a/go.sum b/go.sum index 4d6d740..1ca95a9 100644 --- a/go.sum +++ b/go.sum @@ -55,6 +55,7 @@ github.com/google/go-cmp v0.2.0/go.mod h1:oXzfMopK8JAjlY9xF4vHSVASa0yLyX7SntLO5a github.com/google/go-cmp v0.5.5/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE= github.com/google/go-cmp v0.5.7/go.mod h1:n+brtR0CgQNWTVd5ZUFpTBC8YFBDLK/h/bpaJ8/DtOE= github.com/google/go-cmp v0.5.9 h1:O2Tfq5qg4qc4AmwVlvv0oLiVAGB7enBSJ2x2DqQFi38= +github.com/google/go-cmp v0.5.9/go.mod h1:17dUlkBOakJ0+DkrSSNjCkIjxS6bF9zb3elmeNGIjoY= github.com/google/go-github v17.0.0+incompatible/go.mod h1:zLgOLi98H3fifZn+44m+umXrS52loVEgC2AApnigrVQ= github.com/google/go-querystring v1.0.0/go.mod h1:odCYkC5MyYFN7vkCjXpyrEuKhc/BUO6wN/zVPAxq5ck= github.com/google/martian v2.1.0+incompatible/go.mod h1:9I4somxYTbIHy5NJKHRl3wXiIaQGbYVAs8BPL6v8lEs= @@ -79,11 +80,13 @@ github.com/hashicorp/yamux v0.1.1 h1:yrQxtgseBDrq9Y652vSRDvsKCJKOUD+GzTS4Y0Y8pvE github.com/hashicorp/yamux v0.1.1/go.mod h1:CtWFDAQgb7dxtzFs4tWbplKIe2jSi3+5vKbgIO0SLnQ= github.com/jellevandenhooff/dkim v0.0.0-20150330215556-f50fe3d243e1/go.mod h1:E0B/fFc00Y+Rasa88328GlI/XbtyysCtTHZS8h7IrBU= github.com/jhump/protoreflect v1.6.0 h1:h5jfMVslIg6l29nsMs0D8Wj17RDVdNYti0vDN/PZZoE= +github.com/jhump/protoreflect v1.6.0/go.mod h1:eaTn3RZAmMBcV0fifFvlm6VHNz3wSkYyXYWUh7ymB74= github.com/json-iterator/go v1.1.6/go.mod h1:+SdeFBvtyEkXs7REEP0seUULqWtbJapLOCVDaaPEHmU= github.com/jstemmer/go-junit-report v0.0.0-20190106144839-af01ea7f8024/go.mod h1:6v2b51hI/fHJwM22ozAgKL4VKDeJcHhJFhtBdhmNjmU= github.com/kisielk/gotool v1.0.0/go.mod h1:XhKaO+MFFWcvkIS/tQcRk01m1F5IRFswLeQ+oQHNcck= github.com/kr/pretty v0.1.0/go.mod h1:dAy3ld7l9f0ibDNOQOHHMYYIIbhfbHSm3C4ZsoJORNo= github.com/kr/pretty v0.3.0 h1:WgNl7dwNpEZ6jJ9k1snq4pZsg7DOEN8hP9Xw0Tsjwk0= +github.com/kr/pretty v0.3.0/go.mod h1:640gp4NfQd8pI5XOwp5fnNeVWj67G7CFk/SaSQn7NBk= github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ= github.com/kr/pty v1.1.3/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ= github.com/kr/text v0.1.0 h1:45sCR5RtlFHMR4UwH9sdQ5TC8v0qDQCHnXt+kaKSTVE= @@ -299,6 +302,7 @@ google.golang.org/protobuf v1.31.0 h1:g0LDEJHgrBl9N9r17Ru3sqWhkIx2NB67okBHPwC7hs google.golang.org/protobuf v1.31.0/go.mod h1:HV8QOd/L58Z+nl8r43ehVNZIU/HEI6OcFqwMG9pJV4I= gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c h1:Hei/4ADfdWqJk1ZMxUNpqntNwaWcugrBjAiHlqqRiVk= +gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c/go.mod h1:JHkPIbrfpd72SG/EVd6muEfDQjcINNoR0C8j2r3qZ4Q= gopkg.in/inf.v0 v0.9.1/go.mod h1:cWUDdTG/fYaXco+Dcufb5Vnc6Gp2YChqWtbxRZE0mXw= gopkg.in/natefinch/lumberjack.v2 v2.2.1 h1:bBRl1b0OH9s/DuPhuXpNl+VtCaJXFZ5/uEFST95x9zc= gopkg.in/natefinch/lumberjack.v2 v2.2.1/go.mod h1:YD8tP3GAjkrDg1eZH7EGmyESg/lsYskCTPBJVb9jqSc=