From 5d928b4f942bf86b94d80a9cdcb69c51da5b9f77 Mon Sep 17 00:00:00 2001 From: Shota Gvinepadze Date: Wed, 11 Mar 2020 11:41:11 +0400 Subject: [PATCH] [MM-18150] plugin panic trace should not be lost (#13559) * Transit panic from debug to error * Parse plugin's StdErr and output panic to the mlog.Error * Add unit tests * Change log test * Remove buffer from logger * Remove 'panic' string filter * Change *Buffer to io.Writer Co-authored-by: mattermod --- app/helper_test.go | 12 ++++++++---- app/plugin_test.go | 44 ++++++++++++++++++++++++++++++++++++++++++++ mlog/log.go | 9 +++++++++ mlog/stdlog.go | 10 ++++++++++ mlog/testing.go | 6 ++++-- plugin/supervisor.go | 1 + 6 files changed, 76 insertions(+), 6 deletions(-) diff --git a/app/helper_test.go b/app/helper_test.go index b8292c89ff..69ff372ce8 100644 --- a/app/helper_test.go +++ b/app/helper_test.go @@ -4,6 +4,7 @@ package app import ( + "bytes" "io/ioutil" "os" "path/filepath" @@ -33,11 +34,11 @@ type TestHelper struct { BasicChannel *model.Channel BasicPost *model.Post - SystemAdminUser *model.User + SystemAdminUser *model.User + LogBuffer *bytes.Buffer + IncludeCacheLayer bool tempWorkspace string - - IncludeCacheLayer bool } func setupTestHelper(dbStore store.Store, enterprise bool, includeCacheLayer bool, tb testing.TB, configSet func(*model.Config)) *TestHelper { @@ -59,10 +60,12 @@ func setupTestHelper(dbStore store.Store, enterprise bool, includeCacheLayer boo *config.PluginSettings.ClientDirectory = filepath.Join(tempWorkspace, "webapp") memoryStore.Set(config) + buffer := &bytes.Buffer{} + var options []Option options = append(options, ConfigStore(memoryStore)) options = append(options, StoreOverride(dbStore)) - options = append(options, SetLogger(mlog.NewTestingLogger(tb))) + options = append(options, SetLogger(mlog.NewTestingLogger(tb, buffer))) s, err := NewServer(options...) if err != nil { @@ -77,6 +80,7 @@ func setupTestHelper(dbStore store.Store, enterprise bool, includeCacheLayer boo th := &TestHelper{ App: s.FakeApp(), Server: s, + LogBuffer: buffer, IncludeCacheLayer: includeCacheLayer, } diff --git a/app/plugin_test.go b/app/plugin_test.go index 0b0b573d14..fe59405e6c 100644 --- a/app/plugin_test.go +++ b/app/plugin_test.go @@ -13,6 +13,7 @@ import ( "net/http/httptest" "os" "path/filepath" + "strings" "testing" "time" @@ -626,6 +627,49 @@ func TestPluginSync(t *testing.T) { } } +func TestPluginPanicLogs(t *testing.T) { + t.Run("should panic", func(t *testing.T) { + th := Setup(t).InitBasic() + defer th.TearDown() + tearDown, _, _ := SetAppEnvironmentWithPlugins(t, []string{ + ` + package main + + import ( + "github.com/mattermost/mattermost-server/v5/plugin" + "github.com/mattermost/mattermost-server/v5/model" + ) + + type MyPlugin struct { + plugin.MattermostPlugin + } + + func (p *MyPlugin) MessageWillBePosted(c *plugin.Context, post *model.Post) (*model.Post, string) { + panic("some text from panic") + return nil, "" + } + + func main() { + plugin.ClientMain(&MyPlugin{}) + } + `, + }, th.App, th.App.NewPluginAPI) + defer tearDown() + + post := &model.Post{ + UserId: th.BasicUser.Id, + ChannelId: th.BasicChannel.Id, + Message: "message_", + CreateAt: model.GetMillis() - 10000, + } + _, err := th.App.CreatePost(post, th.BasicChannel, false) + assert.Nil(t, err) + + logs := th.LogBuffer.String() + assert.True(t, strings.Contains(logs, "some text from panic")) + }) +} + func TestProcessPrepackagedPlugins(t *testing.T) { th := Setup(t).InitBasic() defer th.TearDown() diff --git a/mlog/log.go b/mlog/log.go index 1a6c2de949..f2432166f1 100644 --- a/mlog/log.go +++ b/mlog/log.go @@ -144,6 +144,15 @@ func (l *Logger) StdLogWriter() io.Writer { return &loggerWriter{f} } +// StdErrPanicLogWriter returns a writer that can be hooked up to the output of a golang standard logger +// all of the stderr will be interpreted as log entry. +func (l *Logger) StdErrPanicLogWriter() io.Writer { + newLogger := *l + newLogger.zap = newLogger.zap.WithOptions(zap.AddCallerSkip(4), getStdLogOption()) + f := newLogger.Error + return &panicLoggerWriter{f} +} + func (l *Logger) WithCallerSkip(skip int) *Logger { newlogger := *l newlogger.zap = newlogger.zap.WithOptions(zap.AddCallerSkip(skip)) diff --git a/mlog/stdlog.go b/mlog/stdlog.go index fd702abffa..93bacb6d57 100644 --- a/mlog/stdlog.go +++ b/mlog/stdlog.go @@ -85,3 +85,13 @@ func (l *loggerWriter) Write(p []byte) (int, error) { } return len(p), nil } + +type panicLoggerWriter struct { + logFunc func(msg string, fields ...Field) +} + +func (l *panicLoggerWriter) Write(p []byte) (int, error) { + trimmed := string(bytes.TrimSpace(p)) + l.logFunc(trimmed) + return len(p), nil +} diff --git a/mlog/testing.go b/mlog/testing.go index 7a0eb134e2..bf1bcedf43 100644 --- a/mlog/testing.go +++ b/mlog/testing.go @@ -4,6 +4,7 @@ package mlog import ( + "io" "strings" "testing" @@ -23,9 +24,10 @@ func (tw *testingWriter) Write(b []byte) (int, error) { // NewTestingLogger creates a Logger that proxies logs through a testing interface. // This allows tests that spin up App instances to avoid spewing logs unless the test fails or -verbose is specified. -func NewTestingLogger(tb testing.TB) *Logger { +func NewTestingLogger(tb testing.TB, writer io.Writer) *Logger { logWriter := &testingWriter{tb} - logWriterSync := zapcore.AddSync(logWriter) + multiWriter := io.MultiWriter(logWriter, writer) + logWriterSync := zapcore.AddSync(multiWriter) testingLogger := &Logger{ consoleLevel: zap.NewAtomicLevelAt(getZapLevel("debug")), diff --git a/plugin/supervisor.go b/plugin/supervisor.go index 348ea4a46f..40aaf6d6c1 100644 --- a/plugin/supervisor.go +++ b/plugin/supervisor.go @@ -63,6 +63,7 @@ func newSupervisor(pluginInfo *model.BundleInfo, apiImpl API, parentLogger *mlog HandshakeConfig: handshake, Plugins: pluginMap, Cmd: cmd, + Stderr: wrappedLogger.With(mlog.String("source", "plugin_stderr_panic")).StdErrPanicLogWriter(), SyncStdout: wrappedLogger.With(mlog.String("source", "plugin_stdout")).StdLogWriter(), SyncStderr: wrappedLogger.With(mlog.String("source", "plugin_stderr")).StdLogWriter(), Logger: hclogAdaptedLogger,