[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 <mattermod@users.noreply.github.com>

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,
 	}
 

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()

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))

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
+}

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")),

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,