Unverified Commit 83a3ac08 authored by Christopher Speller's avatar Christopher Speller Committed by GitHub

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
parent 3848cb7e
......@@ -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...)
}
......@@ -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)
......
......@@ -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...)
}
......
......@@ -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
}
// 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...)
}
......@@ -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{
......
......@@ -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)
......
This diff is collapsed.
......@@ -6,6 +6,7 @@ package plugin
import (
"fmt"
"log"
"strings"
"github.com/hashicorp/go-hclog"
"github.com/mattermost/mattermost-server/mlog"
......@@ -17,23 +18,48 @@ type HclogAdapter struct {
}
func (h *HclogAdapter) Trace(msg string, args ...interface{}) {
h.wrappedLogger.Debug(msg, mlog.String(h.extrasKey, fmt.Sprintln(args...)))
extras := strings.TrimSpace(fmt.Sprint(args...))
if extras != "" {
h.wrappedLogger.Debug(msg, mlog.String(h.extrasKey, extras))
} else {
h.wrappedLogger.Debug(msg)
}
}
func (h *HclogAdapter) Debug(msg string, args ...interface{}) {
h.wrappedLogger.Debug(msg, mlog.String(h.extrasKey, fmt.Sprintln(args...)))
extras := strings.TrimSpace(fmt.Sprint(args...))
if extras != "" {
h.wrappedLogger.Debug(msg, mlog.String(h.extrasKey, extras))
} else {
h.wrappedLogger.Debug(msg)
}
}
func (h *HclogAdapter) Info(msg string, args ...interface{}) {
h.wrappedLogger.Info(msg, mlog.String(h.extrasKey, fmt.Sprintln(args...)))
extras := strings.TrimSpace(fmt.Sprint(args...))
if extras != "" {
h.wrappedLogger.Info(msg, mlog.String(h.extrasKey, extras))
} else {
h.wrappedLogger.Info(msg)
}
}
func (h *HclogAdapter) Warn(msg string, args ...interface{}) {
h.wrappedLogger.Warn(msg, mlog.String(h.extrasKey, fmt.Sprintln(args...)))
extras := strings.TrimSpace(fmt.Sprint(args...))
if extras != "" {
h.wrappedLogger.Warn(msg, mlog.String(h.extrasKey, extras))
} else {
h.wrappedLogger.Warn(msg)
}
}
func (h *HclogAdapter) Error(msg string, args ...interface{}) {
h.wrappedLogger.Error(msg, mlog.String(h.extrasKey, fmt.Sprintln(args...)))
extras := strings.TrimSpace(fmt.Sprint(args...))
if extras != "" {
h.wrappedLogger.Error(msg, mlog.String(h.extrasKey, extras))
} else {
h.wrappedLogger.Error(msg)
}
}
func (h *HclogAdapter) IsTrace() bool {
......
......@@ -76,12 +76,22 @@ func FieldListDestruct(structPrefix string, fieldList *ast.FieldList, fileset *t
}
nextLetter := 'A'
for _, field := range fieldList.List {
typeNameBuffer := &bytes.Buffer{}
err := printer.Fprint(typeNameBuffer, fileset, field.Type)
if err != nil {
panic(err)
}
typeName := typeNameBuffer.String()
suffix := ""
if strings.HasPrefix(typeName, "...") {
suffix = "..."
}
if len(field.Names) == 0 {
result = append(result, structPrefix+string(nextLetter))
result = append(result, structPrefix+string(nextLetter)+suffix)
nextLetter += 1
} else {
for range field.Names {
result = append(result, structPrefix+string(nextLetter))
result = append(result, structPrefix+string(nextLetter)+suffix)
nextLetter += 1
}
}
......@@ -103,6 +113,9 @@ func FieldListToStructList(fieldList *ast.FieldList, fileset *token.FileSet) str
panic(err)
}
typeName := typeNameBuffer.String()
if strings.HasPrefix(typeName, "...") {
typeName = strings.Replace(typeName, "...", "[]", 1)
}
if len(field.Names) == 0 {
result = append(result, string(nextLetter)+" "+typeName)
nextLetter += 1
......@@ -224,6 +237,8 @@ func (s *HooksRPCServer) {{.Name}}(args *{{.Name}}Args, returns *{{.Name}}Return
{{.Name}}{{funcStyle .Params}} {{funcStyle .Return}}
}); ok {
{{if .Return}}{{destruct "returns." .Return}} = {{end}}hook.{{.Name}}({{destruct "args." .Params}})
} else {
return fmt.Errorf("Hook {{.Name}} called but not implemented.")
}
return nil
}
......@@ -253,6 +268,8 @@ func (s *APIRPCServer) {{.Name}}(args *{{.Name}}Args, returns *{{.Name}}Returns)
{{.Name}}{{funcStyle .Params}} {{funcStyle .Return}}
}); ok {
{{if .Return}}{{destruct "returns." .Return}} = {{end}}hook.{{.Name}}({{destruct "args." .Params}})
} else {
return fmt.Errorf("API {{.Name}} called but not implemented.")
}
return nil
}
......
// Code generated by mockery v1.0.0
// Code generated by mockery v1.0.0. DO NOT EDIT.
// Regenerate this file using `make plugin-mocks`.
......@@ -563,6 +563,38 @@ func (_m *API) LoadPluginConfiguration(dest interface{}) error {
return r0
}
// LogDebug provides a mock function with given fields: msg, keyValuePairs
func (_m *API) LogDebug(msg string, keyValuePairs ...interface{}) {
var _ca []interface{}
_ca = append(_ca, msg)
_ca = append(_ca, keyValuePairs...)
_m.Called(_ca...)
}
// LogError provides a mock function with given fields: msg, keyValuePairs
func (_m *API) LogError(msg string, keyValuePairs ...interface{}) {
var _ca []interface{}
_ca = append(_ca, msg)
_ca = append(_ca, keyValuePairs...)
_m.Called(_ca...)
}
// LogInfo provides a mock function with given fields: msg, keyValuePairs
func (_m *API) LogInfo(msg string, keyValuePairs ...interface{}) {
var _ca []interface{}
_ca = append(_ca, msg)
_ca = append(_ca, keyValuePairs...)
_m.Called(_ca...)
}
// LogWarn provides a mock function with given fields: msg, keyValuePairs
func (_m *API) LogWarn(msg string, keyValuePairs ...interface{}) {
var _ca []interface{}
_ca = append(_ca, msg)
_ca = append(_ca, keyValuePairs...)
_m.Called(_ca...)
}
// PublishWebSocketEvent provides a mock function with given fields: event, payload, broadcast
func (_m *API) PublishWebSocketEvent(event string, payload map[string]interface{}, broadcast *model.WebsocketBroadcast) {
_m.Called(event, payload, broadcast)
......
// Code generated by mockery v1.0.0
// Code generated by mockery v1.0.0. DO NOT EDIT.
// Regenerate this file using `make plugin-mocks`.
......
......@@ -5,7 +5,6 @@ package plugin
import (
"fmt"
"os"
"os/exec"
"path/filepath"
"strings"
......@@ -29,7 +28,7 @@ func NewSupervisor(pluginInfo *model.BundleInfo, parentLogger *mlog.Logger, apiI
wrappedLogger := pluginInfo.WrapLogger(parentLogger)
hclogAdaptedLogger := &HclogAdapter{
wrappedLogger: wrappedLogger,
wrappedLogger: wrappedLogger.WithCallerSkip(1),
extrasKey: "wrapped_extras",
}
......@@ -50,8 +49,8 @@ func NewSupervisor(pluginInfo *model.BundleInfo, parentLogger *mlog.Logger, apiI
HandshakeConfig: Handshake,
Plugins: pluginMap,
Cmd: exec.Command(executable),
SyncStdout: os.Stdout,
SyncStderr: os.Stdout,
SyncStdout: wrappedLogger.With(mlog.String("source", "plugin_stdout")).StdLogWriter(),
SyncStderr: wrappedLogger.With(mlog.String("source", "plugin_stderr")).StdLogWriter(),
Logger: hclogAdaptedLogger,
StartTimeout: time.Second * 3,
})
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment