MM-8622: improved plugin error handling (#8692)

* don't report an error on plugin activation if already active

* improved plugin logging events

Log an error when a plugin's ServeHTTP fails, or when it unexpectedly
terminates.

Restart a plugin at most three times, allowing its failure to later
bubble up under the "failed to stay running" status.

* clarified plugin activation/deactivation

Avoid repeatedly activating when any configuration bit changes. Improved
logging.

* constrain plugin ids to ^[a-zA-Z0-9-_\.]+$ and enforce minimum length

Previously, the plugin id was used unsanitized to relocate the plugin
bundle, which allowed writing outside the `plugins/` directory by using
an `id` containing `../`.

Similarly, an empty string was accepted as an id and led to unexpected
error messages.

* remove plugins by manifest path, not id

If the id within the manifest ever diverges from the actual plugin
location, it becomes impossible to remove via the API. Instead, if the
plugin is found by id, remove the path containing the manifest.

* ignore plugins with nil manifests

If a plugin was detected, but had a manifest that couldn't be parsed, it
will be left nil but still be listed among the packages. Skip over these
in most cases to avoid segfaults.

* leverage mlog more effectively for plugins

* build issues

plugin/rpcplugin/hooks.go

@@ -11,6 +11,7 @@ import (
 	"net/rpc"
 	"reflect"
 
+	"github.com/mattermost/mattermost-server/mlog"
 	"github.com/mattermost/mattermost-server/model"
 	"github.com/mattermost/mattermost-server/plugin"
 )
@@ -165,6 +166,7 @@ type RemoteHooks struct {
 	muxer       *Muxer
 	apiCloser   io.Closer
 	implemented [maxRemoteHookCount]bool
+	pluginId    string
 }
 
 var _ plugin.Hooks = (*RemoteHooks)(nil)
@@ -237,6 +239,7 @@ func (h *RemoteHooks) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 		Request:              forwardedRequest,
 		RequestBodyStream:    requestBodyStream,
 	}, nil); err != nil {
+		mlog.Error("Plugin failed to ServeHTTP", mlog.String("plugin_id", h.pluginId), mlog.Err(err))
 		http.Error(w, "500 internal server error", http.StatusInternalServerError)
 	}
 }
@@ -260,10 +263,11 @@ func (h *RemoteHooks) Close() error {
 	return h.client.Close()
 }
 
-func ConnectHooks(conn io.ReadWriteCloser, muxer *Muxer) (*RemoteHooks, error) {
+func ConnectHooks(conn io.ReadWriteCloser, muxer *Muxer, pluginId string) (*RemoteHooks, error) {
 	remote := &RemoteHooks{
-		client: rpc.NewClient(conn),
-		muxer:  muxer,
+		client:   rpc.NewClient(conn),
+		muxer:    muxer,
+		pluginId: pluginId,
 	}
 	implemented, err := remote.Implemented()
 	if err != nil {

plugin/rpcplugin/hooks_test.go

@@ -31,7 +31,7 @@ func testHooksRPC(hooks interface{}, f func(*RemoteHooks)) error {
 	id, server := c1.Serve()
 	go ServeHooks(hooks, server, c1)
 
-	remote, err := ConnectHooks(c2.Connect(id), c2)
+	remote, err := ConnectHooks(c2.Connect(id), c2, "plugin_id")
 	if err != nil {
 		return err
 	}

plugin/rpcplugin/main.go

@@ -30,7 +30,7 @@ func Main(hooks interface{}) {
 }
 
 // Returns the hooks being served by a call to Main.
-func ConnectMain(muxer *Muxer) (*RemoteHooks, error) {
+func ConnectMain(muxer *Muxer, pluginId string) (*RemoteHooks, error) {
 	buf := make([]byte, 1)
 	if _, err := muxer.Read(buf); err != nil {
 		return nil, err
@@ -43,5 +43,5 @@ func ConnectMain(muxer *Muxer) (*RemoteHooks, error) {
 		return nil, err
 	}
 
-	return ConnectHooks(muxer.Connect(id), muxer)
+	return ConnectHooks(muxer.Connect(id), muxer, pluginId)
 }

plugin/rpcplugin/main_test.go

@@ -10,11 +10,21 @@ import (
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 
+	"github.com/mattermost/mattermost-server/mlog"
 	"github.com/mattermost/mattermost-server/plugin/plugintest"
 	"github.com/mattermost/mattermost-server/plugin/rpcplugin/rpcplugintest"
 )
 
 func TestMain(t *testing.T) {
+	// Setup a global logger to catch tests logging outside of app context
+	// The global logger will be stomped by apps initalizing but that's fine for testing. Ideally this won't happen.
+	mlog.InitGlobalLogger(mlog.NewLogger(&mlog.LoggerConfiguration{
+		EnableConsole: true,
+		ConsoleJson:   true,
+		ConsoleLevel:  "error",
+		EnableFile:    false,
+	}))
+
 	dir, err := ioutil.TempDir("", "")
 	require.NoError(t, err)
 	defer os.RemoveAll(dir)
@@ -46,7 +56,7 @@ func TestMain(t *testing.T) {
 
 	var api plugintest.API
 
-	hooks, err := ConnectMain(muxer)
+	hooks, err := ConnectMain(muxer, "plugin_id")
 	require.NoError(t, err)
 	assert.NoError(t, hooks.OnActivate(&api))
 	assert.NoError(t, hooks.OnDeactivate())

plugin/rpcplugin/rpcplugintest/supervisor.go

@@ -7,6 +7,8 @@ import (
 	"encoding/json"
 	"fmt"
 	"io/ioutil"
+	"net/http"
+	"net/http/httptest"
 	"os"
 	"path/filepath"
 	"testing"
@@ -30,6 +32,7 @@ func TestSupervisorProvider(t *testing.T, sp SupervisorProviderFunc) {
 		"Supervisor_NonExistentExecutablePath": testSupervisor_NonExistentExecutablePath,
 		"Supervisor_StartTimeout":              testSupervisor_StartTimeout,
 		"Supervisor_PluginCrash":               testSupervisor_PluginCrash,
+		"Supervisor_PluginRepeatedlyCrash":     testSupervisor_PluginRepeatedlyCrash,
 	} {
 		t.Run(name, func(t *testing.T) { f(t, sp) })
 	}
@@ -188,3 +191,83 @@ func testSupervisor_PluginCrash(t *testing.T, sp SupervisorProviderFunc) {
 	assert.True(t, recovered)
 	require.NoError(t, supervisor.Stop())
 }
+
+// Crashed plugins should be relaunched at most three times.
+func testSupervisor_PluginRepeatedlyCrash(t *testing.T, sp SupervisorProviderFunc) {
+	dir, err := ioutil.TempDir("", "")
+	require.NoError(t, err)
+	defer os.RemoveAll(dir)
+
+	backend := filepath.Join(dir, "backend.exe")
+	CompileGo(t, `
+		package main
+
+		import (
+			"net/http"
+			"os"
+
+			"github.com/mattermost/mattermost-server/plugin/rpcplugin"
+		)
+
+		type MyPlugin struct {
+			crashing bool
+		}
+
+		func (p *MyPlugin) ServeHTTP(w http.ResponseWriter, r *http.Request) {
+			if r.Method == http.MethodPost {
+				p.crashing = true
+				go func() {
+					os.Exit(1)
+				}()
+			}
+
+			if p.crashing {
+				w.WriteHeader(http.StatusInternalServerError)
+			} else {
+				w.WriteHeader(http.StatusOK)
+			}
+		}
+
+		func main() {
+			rpcplugin.Main(&MyPlugin{})
+		}
+	`, backend)
+
+	ioutil.WriteFile(filepath.Join(dir, "plugin.json"), []byte(`{"id": "foo", "backend": {"executable": "backend.exe"}}`), 0600)
+
+	var api plugintest.API
+	bundle := model.BundleInfoForPath(dir)
+	supervisor, err := sp(bundle)
+	require.NoError(t, err)
+	require.NoError(t, supervisor.Start(&api))
+
+	for attempt := 1; attempt <= 4; attempt++ {
+		// Verify that the plugin is operational
+		response := httptest.NewRecorder()
+		supervisor.Hooks().ServeHTTP(response, httptest.NewRequest(http.MethodGet, "/plugins/id", nil))
+		require.Equal(t, http.StatusOK, response.Result().StatusCode)
+
+		// Crash the plugin
+		supervisor.Hooks().ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(http.MethodPost, "/plugins/id", nil))
+
+		// Wait for it to potentially recover
+		recovered := false
+		for i := 0; i < 125; i++ {
+			response := httptest.NewRecorder()
+			supervisor.Hooks().ServeHTTP(response, httptest.NewRequest(http.MethodGet, "/plugins/id", nil))
+			if response.Result().StatusCode == http.StatusOK {
+				recovered = true
+				break
+			}
+
+			time.Sleep(time.Millisecond * 100)
+		}
+
+		if attempt < 4 {
+			require.True(t, recovered, "failed to recover after attempt %d", attempt)
+		} else {
+			require.False(t, recovered, "unexpectedly recovered after attempt %d", attempt)
+		}
+	}
+	require.NoError(t, supervisor.Stop())
+}

plugin/rpcplugin/sandbox/main_test.go

@@ -0,0 +1,18 @@
+package sandbox
+
+import (
+	"testing"
+
+	"github.com/mattermost/mattermost-server/mlog"
+)
+
+func TestMain(t *testing.T) {
+	// Setup a global logger to catch tests logging outside of app context
+	// The global logger will be stomped by apps initalizing but that's fine for testing. Ideally this won't happen.
+	mlog.InitGlobalLogger(mlog.NewLogger(&mlog.LoggerConfiguration{
+		EnableConsole: true,
+		ConsoleJson:   true,
+		ConsoleLevel:  "error",
+		EnableFile:    false,
+	}))
+}

plugin/rpcplugin/supervisor.go

@@ -12,19 +12,26 @@ import (
 	"sync/atomic"
 	"time"
 
+	"github.com/mattermost/mattermost-server/mlog"
 	"github.com/mattermost/mattermost-server/model"
 	"github.com/mattermost/mattermost-server/plugin"
 )
 
+const (
+	MaxProcessRestarts = 3
+)
+
 // Supervisor implements a plugin.Supervisor that launches the plugin in a separate process and
 // communicates via RPC.
 //
-// If the plugin unexpectedly exists, the supervisor will relaunch it after a short delay.
+// If the plugin unexpectedly exits, the supervisor will relaunch it after a short delay, but will
+// only restart a plugin at most three times.
 type Supervisor struct {
 	hooks      atomic.Value
 	done       chan bool
 	cancel     context.CancelFunc
 	newProcess func(context.Context) (Process, io.ReadWriteCloser, error)
+	pluginId   string
 }
 
 var _ plugin.Supervisor = (*Supervisor)(nil)
@@ -66,19 +73,28 @@ func (s *Supervisor) run(ctx context.Context, start chan<- error, api plugin.API
 		s.done <- true
 	}()
 	done := ctx.Done()
-	for {
+	for i := 0; i <= MaxProcessRestarts; i++ {
 		s.runPlugin(ctx, start, api)
 		select {
 		case <-done:
 			return
 		default:
 			start = nil
-			time.Sleep(time.Second)
+			if i < MaxProcessRestarts {
+				mlog.Debug("Plugin terminated unexpectedly", mlog.String("plugin_id", s.pluginId))
+				time.Sleep(time.Duration((1 + i*i)) * time.Second)
+			} else {
+				mlog.Debug("Plugin terminated unexpectedly too many times", mlog.String("plugin_id", s.pluginId), mlog.Int("max_process_restarts", MaxProcessRestarts))
+			}
 		}
 	}
 }
 
 func (s *Supervisor) runPlugin(ctx context.Context, start chan<- error, api plugin.API) error {
+	if start == nil {
+		mlog.Debug("Restarting plugin", mlog.String("plugin_id", s.pluginId))
+	}
+
 	p, ipc, err := s.newProcess(ctx)
 	if err != nil {
 		if start != nil {
@@ -100,7 +116,7 @@ func (s *Supervisor) runPlugin(ctx context.Context, start chan<- error, api plug
 		muxerClosed <- muxer.Close()
 	}()
 
-	hooks, err := ConnectMain(muxer)
+	hooks, err := ConnectMain(muxer, s.pluginId)
 	if err == nil {
 		err = hooks.OnActivate(api)
 	}
@@ -147,5 +163,5 @@ func SupervisorWithNewProcessFunc(bundle *model.BundleInfo, newProcess func(cont
 	if strings.HasPrefix(executable, "..") {
 		return nil, fmt.Errorf("invalid backend executable")
 	}
-	return &Supervisor{newProcess: newProcess}, nil
+	return &Supervisor{pluginId: bundle.Manifest.Id, newProcess: newProcess}, nil
 }