MM-11029 Adding plugin logging functionality. (#9034)

* Capturing stdout, stderr of plugins in logs.

* Cleanup go-plugin debug logs.

* Adding logging to plugin API

* Generating mocks.

* godoc convention

app/plugin_api.go

@@ -7,18 +7,21 @@ import (
 	"encoding/json"
 	"fmt"
 
+	"github.com/mattermost/mattermost-server/mlog"
 	"github.com/mattermost/mattermost-server/model"
 )
 
 type PluginAPI struct {
-	id  string
-	app *App
+	id     string
+	app    *App
+	logger *mlog.SugarLogger
 }
 
 func NewPluginAPI(a *App, manifest *model.Manifest) *PluginAPI {
 	return &PluginAPI{
-		id:  manifest.Id,
-		app: a,
+		id:     manifest.Id,
+		app:    a,
+		logger: a.Log.With(mlog.String("plugin_id", manifest.Id)).Sugar(),
 	}
 }
 
@@ -185,3 +188,16 @@ func (api *PluginAPI) PublishWebSocketEvent(event string, payload map[string]int
 		Broadcast: broadcast,
 	})
 }
+
+func (api *PluginAPI) LogDebug(msg string, keyValuePairs ...interface{}) {
+	api.logger.Debug(msg, keyValuePairs...)
+}
+func (api *PluginAPI) LogInfo(msg string, keyValuePairs ...interface{}) {
+	api.logger.Info(msg, keyValuePairs...)
+}
+func (api *PluginAPI) LogError(msg string, keyValuePairs ...interface{}) {
+	api.logger.Error(msg, keyValuePairs...)
+}
+func (api *PluginAPI) LogWarn(msg string, keyValuePairs ...interface{}) {
+	api.logger.Warn(msg, keyValuePairs...)
+}

mlog/global.go

@@ -11,7 +11,9 @@ import (
 var globalLogger *Logger
 
 func InitGlobalLogger(logger *Logger) {
-	globalLogger = logger
+	glob := *logger
+	glob.zap = glob.zap.WithOptions(zap.AddCallerSkip(1))
+	globalLogger = &glob
 	Debug = globalLogger.Debug
 	Info = globalLogger.Info
 	Warn = globalLogger.Warn
@@ -20,7 +22,7 @@ func InitGlobalLogger(logger *Logger) {
 }
 
 func RedirectStdLog(logger *Logger) {
-	zap.RedirectStdLogAt(logger.zap.With(zap.String("source", "stdlog")), zapcore.ErrorLevel)
+	zap.RedirectStdLogAt(logger.zap.With(zap.String("source", "stdlog")).WithOptions(zap.AddCallerSkip(-2)), zapcore.ErrorLevel)
 }
 
 type LogFunc func(string, ...Field)

mlog/log.go

@@ -4,6 +4,7 @@
 package mlog
 
 import (
+	"io"
 	"log"
 	"os"
 
@@ -101,7 +102,7 @@ func NewLogger(config *LoggerConfiguration) *Logger {
 	combinedCore := zapcore.NewTee(cores...)
 
 	logger.zap = zap.New(combinedCore,
-		zap.AddCallerSkip(2),
+		zap.AddCallerSkip(1),
 		zap.AddCaller(),
 	)
 
@@ -127,6 +128,30 @@ func (l *Logger) StdLog(fields ...Field) *log.Logger {
 	return zap.NewStdLog(l.With(fields...).zap.WithOptions(getStdLogOption()))
 }
 
+// StdLogWriter returns a writer that can be hooked up to the output of a golang standard logger
+// anything written will be interpreted as log entries accordingly
+func (l *Logger) StdLogWriter() io.Writer {
+	newLogger := *l
+	newLogger.zap = newLogger.zap.WithOptions(zap.AddCallerSkip(4), getStdLogOption())
+	f := newLogger.Info
+	return &loggerWriter{f}
+}
+
+func (l *Logger) WithCallerSkip(skip int) *Logger {
+	newlogger := *l
+	newlogger.zap = newlogger.zap.WithOptions(zap.AddCallerSkip(skip))
+	return &newlogger
+}
+
+// Made for the plugin interface, wraps mlog in a simpler interface
+// at the cost of performance
+func (l *Logger) Sugar() *SugarLogger {
+	return &SugarLogger{
+		wrappedLogger: l,
+		zapSugar:      l.zap.Sugar(),
+	}
+}
+
 func (l *Logger) Debug(message string, fields ...Field) {
 	l.zap.Debug(message, fields...)
 }

mlog/stdlog.go

@@ -4,6 +4,7 @@
 package mlog
 
 import (
+	"bytes"
 	"strings"
 
 	"go.uber.org/zap"
@@ -72,3 +73,15 @@ func getStdLogOption() zap.Option {
 		},
 	)
 }
+
+type loggerWriter struct {
+	logFunc func(msg string, fields ...Field)
+}
+
+func (l *loggerWriter) Write(p []byte) (int, error) {
+	trimmed := string(bytes.TrimSpace(p))
+	for _, line := range strings.Split(trimmed, "\n") {
+		l.logFunc(string(line))
+	}
+	return len(p), nil
+}

mlog/sugar.go

@@ -0,0 +1,28 @@
+// Copyright (c) 2015-present Mattermost, Inc. All Rights Reserved.
+// See LICENSE.txt for license information.
+
+package mlog
+
+import "go.uber.org/zap"
+
+// Made for the plugin interface, use the regular logger for other uses
+type SugarLogger struct {
+	wrappedLogger *Logger
+	zapSugar      *zap.SugaredLogger
+}
+
+func (l *SugarLogger) Debug(msg string, keyValuePairs ...interface{}) {
+	l.zapSugar.Debugw(msg, keyValuePairs...)
+}
+
+func (l *SugarLogger) Info(msg string, keyValuePairs ...interface{}) {
+	l.zapSugar.Infow(msg, keyValuePairs...)
+}
+
+func (l *SugarLogger) Error(msg string, keyValuePairs ...interface{}) {
+	l.zapSugar.Errorw(msg, keyValuePairs...)
+}
+
+func (l *SugarLogger) Warn(msg string, keyValuePairs ...interface{}) {
+	l.zapSugar.Warnw(msg, keyValuePairs...)
+}

plugin/api.go

@@ -119,6 +119,30 @@ type API interface {
 	// payload is the data sent with the event. Interface values must be primitive Go types or mattermost-server/model types
 	// broadcast determines to which users to send the event
 	PublishWebSocketEvent(event string, payload map[string]interface{}, broadcast *model.WebsocketBroadcast)
+
+	// LogDebug writes a log message to the Mattermost server log file.
+	// Appropriate context such as the plugin name will already be added as fields so plugins
+	// do not need to add that info.
+	// keyValuePairs should be primitive go types or other values that can be encoded by encoding/gob
+	LogDebug(msg string, keyValuePairs ...interface{})
+
+	// LogInfo writes a log message to the Mattermost server log file.
+	// Appropriate context such as the plugin name will already be added as fields so plugins
+	// do not need to add that info.
+	// keyValuePairs should be primitive go types or other values that can be encoded by encoding/gob
+	LogInfo(msg string, keyValuePairs ...interface{})
+
+	// LogError writes a log message to the Mattermost server log file.
+	// Appropriate context such as the plugin name will already be added as fields so plugins
+	// do not need to add that info.
+	// keyValuePairs should be primitive go types or other values that can be encoded by encoding/gob
+	LogError(msg string, keyValuePairs ...interface{})
+
+	// LogWarn writes a log message to the Mattermost server log file.
+	// Appropriate context such as the plugin name will already be added as fields so plugins
+	// do not need to add that info.
+	// keyValuePairs should be primitive go types or other values that can be encoded by encoding/gob
+	LogWarn(msg string, keyValuePairs ...interface{})
 }
 
 var Handshake = plugin.HandshakeConfig{

plugin/client_rpc.go

@@ -9,9 +9,12 @@ import (
 	"bytes"
 	"encoding/gob"
 	"encoding/json"
+	"fmt"
 	"io/ioutil"
+	"log"
 	"net/http"
 	"net/rpc"
+	"os"
 	"reflect"
 
 	"github.com/hashicorp/go-plugin"
@@ -33,7 +36,6 @@ type HooksRPCServer struct {
 	impl         interface{}
 	muxBroker    *plugin.MuxBroker
 	apiRPCClient *APIRPCClient
-	log          *mlog.Logger
 }
 
 // Implements hashicorp/go-plugin/plugin.Plugin interface to connect the hooks of a plugin
@@ -156,24 +158,11 @@ func (g *HooksRPCClient) OnActivate() error {
 func (s *HooksRPCServer) OnActivate(args *OnActivateArgs, returns *OnActivateReturns) error {
 	connection, err := s.muxBroker.Dial(args.APIMuxId)
 	if err != nil {
-		return err // Where does this go?
+		return err
 	}
 
-	// Settings for this should come from the parent process, for now just set it up
-	// though stdout.
-	logger := mlog.NewLogger(&mlog.LoggerConfiguration{
-		EnableConsole: true,
-		ConsoleJson:   true,
-		ConsoleLevel:  mlog.LevelDebug,
-		EnableFile:    false,
-	})
-	logger = logger.With(mlog.Bool("plugin_subprocess", true))
-
-	s.log = logger
-
 	s.apiRPCClient = &APIRPCClient{
 		client: rpc.NewClient(connection),
-		log:    logger,
 	}
 
 	if mmplugin, ok := s.impl.(interface {
@@ -185,6 +174,10 @@ func (s *HooksRPCServer) OnActivate(args *OnActivateArgs, returns *OnActivateRet
 		mmplugin.OnConfigurationChange()
 	}
 
+	// Capture output of standard logger because go-plugin
+	// redirects it.
+	log.SetOutput(os.Stderr)
+
 	if hook, ok := s.impl.(interface {
 		OnActivate() error
 	}); ok {
@@ -293,7 +286,7 @@ func (g *HooksRPCClient) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 		Request:              forwardedRequest,
 		RequestBodyStream:    requestBodyStreamId,
 	}, nil); err != nil {
-		mlog.Error("Plugin failed to ServeHTTP, RPC call failed", mlog.Err(err))
+		g.log.Error("Plugin failed to ServeHTTP, RPC call failed", mlog.Err(err))
 		http.Error(w, "500 internal server error", http.StatusInternalServerError)
 	}
 	return
@@ -302,7 +295,7 @@ func (g *HooksRPCClient) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 func (s *HooksRPCServer) ServeHTTP(args *ServeHTTPArgs, returns *struct{}) error {
 	connection, err := s.muxBroker.Dial(args.ResponseWriterStream)
 	if err != nil {
-		s.log.Debug("Can't connect to remote response writer stream", mlog.Err(err))
+		fmt.Fprintf(os.Stderr, "[ERROR] Can't connect to remote response writer stream, error: %v", err.Error())
 		return err
 	}
 	w := ConnectHTTPResponseWriter(connection)
@@ -312,7 +305,7 @@ func (s *HooksRPCServer) ServeHTTP(args *ServeHTTPArgs, returns *struct{}) error
 	if args.RequestBodyStream != 0 {
 		connection, err := s.muxBroker.Dial(args.RequestBodyStream)
 		if err != nil {
-			s.log.Debug("Can't connect to remote response writer stream", mlog.Err(err))
+			fmt.Fprintf(os.Stderr, "[ERROR] Can't connect to remote request body stream, error: %v", err.Error())
 			return err
 		}
 		r.Body = ConnectIOReader(connection)