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

11 files changed, 213 insertions, 14 deletions

diff --git a/plugin/pluginenv/environment.go b/plugin/pluginenv/environment.go
index adc9ddbde..adc02e885 100644
--- a/plugin/pluginenv/environment.go
+++ b/plugin/pluginenv/environment.go
@@ -112,8 +112,12 @@ func (env *Environment) ActivatePlugin(id string) error {
 	env.mutex.Lock()
 	defer env.mutex.Unlock()
 
+	if !plugin.IsValidId(id) {
+		return fmt.Errorf("invalid plugin id: %s", id)
+	}
+
 	if _, ok := env.activePlugins[id]; ok {
-		return fmt.Errorf("plugin already active: %v", id)
+		return nil
 	}
 	plugins, err := ScanSearchPath(env.searchPath)
 	if err != nil {
diff --git a/plugin/pluginenv/environment_test.go b/plugin/pluginenv/environment_test.go
index 2a52b3830..91d639f69 100644
--- a/plugin/pluginenv/environment_test.go
+++ b/plugin/pluginenv/environment_test.go
@@ -149,7 +149,7 @@ func TestEnvironment(t *testing.T) {
 	assert.Equal(t, env.ActivePluginIds(), []string{"foo"})
 	activePlugins = env.ActivePlugins()
 	assert.Len(t, activePlugins, 1)
-	assert.Error(t, env.ActivatePlugin("foo"))
+	assert.NoError(t, env.ActivatePlugin("foo"))
 	assert.True(t, env.IsPluginActive("foo"))
 
 	hooks.On("OnDeactivate").Return(nil)
diff --git a/plugin/rpcplugin/hooks.go b/plugin/rpcplugin/hooks.go
index 7b44d0de7..90734fd1c 100644
--- a/plugin/rpcplugin/hooks.go
+++ b/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 {
diff --git a/plugin/rpcplugin/hooks_test.go b/plugin/rpcplugin/hooks_test.go
index 116038dae..c404442b7 100644
--- a/plugin/rpcplugin/hooks_test.go
+++ b/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
 	}
diff --git a/plugin/rpcplugin/main.go b/plugin/rpcplugin/main.go
index 96a61c068..efb880605 100644
--- a/plugin/rpcplugin/main.go
+++ b/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)
 }
diff --git a/plugin/rpcplugin/main_test.go b/plugin/rpcplugin/main_test.go
index 6cdd46df0..06423106c 100644
--- a/plugin/rpcplugin/main_test.go
+++ b/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())
diff --git a/plugin/rpcplugin/rpcplugintest/supervisor.go b/plugin/rpcplugin/rpcplugintest/supervisor.go
index 05dc8ed8f..2ae065621 100644
--- a/plugin/rpcplugin/rpcplugintest/supervisor.go
+++ b/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())
+}
diff --git a/plugin/rpcplugin/sandbox/main_test.go b/plugin/rpcplugin/sandbox/main_test.go
new file mode 100644
index 000000000..4be4a42af
--- /dev/null
+++ b/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,
+	}))
+}
diff --git a/plugin/rpcplugin/supervisor.go b/plugin/rpcplugin/supervisor.go
index 6a48cb5e8..6e26d5682 100644
--- a/plugin/rpcplugin/supervisor.go
+++ b/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
 }
diff --git a/plugin/valid.go b/plugin/valid.go
new file mode 100644
index 000000000..62c594a1a
--- /dev/null
+++ b/plugin/valid.go
@@ -0,0 +1,32 @@
+// Copyright (c) 2015-present Mattermost, Inc. All Rights Reserved.
+// See License.txt for license information.
+
+package plugin
+
+import (
+	"regexp"
+	"unicode/utf8"
+)
+
+const (
+	MinIdLength = 3
+	MaxIdLength = 190
+)
+
+var ValidId *regexp.Regexp
+
+func init() {
+	ValidId = regexp.MustCompile(`^[a-zA-Z0-9-_\.]+$`)
+}
+
+func IsValidId(id string) bool {
+	if utf8.RuneCountInString(id) < MinIdLength {
+		return false
+	}
+
+	if utf8.RuneCountInString(id) > MaxIdLength {
+		return false
+	}
+
+	return ValidId.MatchString(id)
+}
diff --git a/plugin/valid_test.go b/plugin/valid_test.go
new file mode 100644
index 000000000..d47eeb58b
--- /dev/null
+++ b/plugin/valid_test.go
@@ -0,0 +1,32 @@
+package plugin_test
+
+import (
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+
+	"github.com/mattermost/mattermost-server/plugin"
+)
+
+func TestIsValid(t *testing.T) {
+	t.Parallel()
+
+	testCases := map[string]bool{
+		"":    false,
+		"a":   false,
+		"ab":  false,
+		"abc": true,
+		"abcdefghijabcdefghijabcdefghijabcdefghijabcdefghijabcdefghijabcdefghijabcdefghijabcdefghijabcdefghijabcdefghijabcdefghijabcdefghijabcdefghijabcdefghijabcdefghijabcdefghijabcdefghijabcdefghij":  true,
+		"abcdefghijabcdefghijabcdefghijabcdefghijabcdefghijabcdefghijabcdefghijabcdefghijabcdefghijabcdefghijabcdefghijabcdefghijabcdefghijabcdefghijabcdefghijabcdefghijabcdefghijabcdefghijabcdefghij1": false,
+		"../path":                                 false,
+		"/etc/passwd":                             false,
+		"com.mattermost.plugin_with_features-0.9": true,
+		"PLUGINS-THAT-YELL-ARE-OK-2":              true,
+	}
+
+	for id, valid := range testCases {
+		t.Run(id, func(t *testing.T) {
+			assert.Equal(t, valid, plugin.IsValidId(id))
+		})
+	}
+}