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

1 files changed, 36 insertions, 37 deletions

diff --git a/app/plugin.go b/app/plugin.go
index 3da9cea40..0aaa8d1d4 100644
--- a/app/plugin.go
+++ b/app/plugin.go
@@ -15,7 +15,6 @@ import (
 	"os"
 	"path/filepath"
 	"strings"
-	"unicode/utf8"
 
 	"github.com/gorilla/mux"
 	"github.com/mattermost/mattermost-server/mlog"
@@ -33,10 +32,6 @@ import (
 	"github.com/mattermost/mattermost-server/plugin/rpcplugin/sandbox"
 )
 
-const (
-	PLUGIN_MAX_ID_LENGTH = 190
-)
-
 var prepackagedPlugins map[string]func(string) ([]byte, error) = map[string]func(string) ([]byte, error){
 	"jira": jira.Asset,
 	"zoom": zoom.Asset,
@@ -47,7 +42,7 @@ func (a *App) initBuiltInPlugins() {
 		"ldapextras": &ldapextras.Plugin{},
 	}
 	for id, p := range plugins {
-		mlog.Debug("Initializing built-in plugin: " + id)
+		mlog.Debug("Initializing built-in plugin", mlog.String("plugin_id", id))
 		api := &BuiltInPluginAPI{
 			id:     id,
 			router: a.Srv.Router.PathPrefix("/plugins/" + id).Subrouter(),
@@ -65,21 +60,23 @@ func (a *App) initBuiltInPlugins() {
 	}
 }
 
-// ActivatePlugins will activate any plugins enabled in the config
-// and deactivate all other plugins.
-func (a *App) ActivatePlugins() {
+func (a *App) setPluginsActive(activate bool) {
 	if a.PluginEnv == nil {
-		mlog.Error("plugin env not initialized")
+		mlog.Error(fmt.Sprintf("Cannot setPluginsActive(%t): plugin env not initialized", activate))
 		return
 	}
 
 	plugins, err := a.PluginEnv.Plugins()
 	if err != nil {
-		mlog.Error("failed to activate plugins: " + err.Error())
+		mlog.Error(fmt.Sprintf("Cannot setPluginsActive(%t)", activate), mlog.Err(err))
 		return
 	}
 
 	for _, plugin := range plugins {
+		if plugin.Manifest == nil {
+			continue
+		}
+
 		id := plugin.Manifest.Id
 
 		pluginState := &model.PluginState{Enable: false}
@@ -89,15 +86,14 @@ func (a *App) ActivatePlugins() {
 
 		active := a.PluginEnv.IsPluginActive(id)
 
-		if pluginState.Enable && !active {
+		if activate && pluginState.Enable && !active {
 			if err := a.activatePlugin(plugin.Manifest); err != nil {
-				mlog.Error(fmt.Sprintf("%v plugin enabled in config.json but failing to activate err=%v", plugin.Manifest.Id, err.DetailedError))
-				continue
+				mlog.Error("Plugin failed to activate", mlog.String("plugin_id", plugin.Manifest.Id), mlog.String("err", err.DetailedError))
 			}
 
-		} else if !pluginState.Enable && active {
+		} else if (!activate || !pluginState.Enable) && active {
 			if err := a.deactivatePlugin(plugin.Manifest); err != nil {
-				mlog.Error(err.Error())
+				mlog.Error("Plugin failed to deactivate", mlog.String("plugin_id", plugin.Manifest.Id), mlog.String("err", err.DetailedError))
 			}
 		}
 	}
@@ -114,13 +110,13 @@ func (a *App) activatePlugin(manifest *model.Manifest) *model.AppError {
 		a.Publish(message)
 	}
 
-	mlog.Info(fmt.Sprintf("Activated %v plugin", manifest.Id))
+	mlog.Info("Activated plugin", mlog.String("plugin_id", manifest.Id))
 	return nil
 }
 
 func (a *App) deactivatePlugin(manifest *model.Manifest) *model.AppError {
 	if err := a.PluginEnv.DeactivatePlugin(manifest.Id); err != nil {
-		return model.NewAppError("removePlugin", "app.plugin.deactivate.app_error", nil, err.Error(), http.StatusBadRequest)
+		return model.NewAppError("deactivatePlugin", "app.plugin.deactivate.app_error", nil, err.Error(), http.StatusBadRequest)
 	}
 
 	a.UnregisterPluginCommands(manifest.Id)
@@ -131,7 +127,7 @@ func (a *App) deactivatePlugin(manifest *model.Manifest) *model.AppError {
 		a.Publish(message)
 	}
 
-	mlog.Info(fmt.Sprintf("Deactivated %v plugin", manifest.Id))
+	mlog.Info("Deactivated plugin", mlog.String("plugin_id", manifest.Id))
 	return nil
 }
 
@@ -174,8 +170,8 @@ func (a *App) installPlugin(pluginFile io.Reader, allowPrepackaged bool) (*model
 		return nil, model.NewAppError("installPlugin", "app.plugin.prepackaged.app_error", nil, "", http.StatusBadRequest)
 	}
 
-	if utf8.RuneCountInString(manifest.Id) > PLUGIN_MAX_ID_LENGTH {
-		return nil, model.NewAppError("installPlugin", "app.plugin.id_length.app_error", map[string]interface{}{"Max": PLUGIN_MAX_ID_LENGTH}, err.Error(), http.StatusBadRequest)
+	if !plugin.IsValidId(manifest.Id) {
+		return nil, model.NewAppError("installPlugin", "app.plugin.invalid_id.app_error", map[string]interface{}{"Min": plugin.MinIdLength, "Max": plugin.MaxIdLength, "Regex": plugin.ValidId.String()}, "", http.StatusBadRequest)
 	}
 
 	bundles, err := a.PluginEnv.Plugins()
@@ -184,7 +180,7 @@ func (a *App) installPlugin(pluginFile io.Reader, allowPrepackaged bool) (*model
 	}
 
 	for _, bundle := range bundles {
-		if bundle.Manifest.Id == manifest.Id {
+		if bundle.Manifest != nil && bundle.Manifest.Id == manifest.Id {
 			return nil, model.NewAppError("installPlugin", "app.plugin.install_id.app_error", nil, "", http.StatusBadRequest)
 		}
 	}
@@ -211,6 +207,10 @@ func (a *App) GetPlugins() (*model.PluginsResponse, *model.AppError) {
 
 	resp := &model.PluginsResponse{Active: []*model.PluginInfo{}, Inactive: []*model.PluginInfo{}}
 	for _, plugin := range plugins {
+		if plugin.Manifest == nil {
+			continue
+		}
+
 		info := &model.PluginInfo{
 			Manifest: *plugin.Manifest,
 		}
@@ -259,9 +259,11 @@ func (a *App) removePlugin(id string, allowPrepackaged bool) *model.AppError {
 	}
 
 	var manifest *model.Manifest
+	var pluginPath string
 	for _, p := range plugins {
-		if p.Manifest.Id == id {
+		if p.Manifest != nil && p.Manifest.Id == id {
 			manifest = p.Manifest
+			pluginPath = filepath.Dir(p.ManifestPath)
 			break
 		}
 	}
@@ -277,7 +279,7 @@ func (a *App) removePlugin(id string, allowPrepackaged bool) *model.AppError {
 		}
 	}
 
-	err = os.RemoveAll(filepath.Join(a.PluginEnv.SearchPath(), id))
+	err = os.RemoveAll(pluginPath)
 	if err != nil {
 		return model.NewAppError("removePlugin", "app.plugin.remove.app_error", nil, err.Error(), http.StatusInternalServerError)
 	}
@@ -372,12 +374,12 @@ func (a *App) InitPlugins(pluginPath, webappPath string, supervisorOverride plug
 	mlog.Info("Starting up plugins")
 
 	if err := os.Mkdir(pluginPath, 0744); err != nil && !os.IsExist(err) {
-		mlog.Error("failed to start up plugins: " + err.Error())
+		mlog.Error("Failed to start up plugins", mlog.Err(err))
 		return
 	}
 
 	if err := os.Mkdir(webappPath, 0744); err != nil && !os.IsExist(err) {
-		mlog.Error("failed to start up plugins: " + err.Error())
+		mlog.Error("Failed to start up plugins", mlog.Err(err))
 		return
 	}
 
@@ -399,15 +401,14 @@ func (a *App) InitPlugins(pluginPath, webappPath string, supervisorOverride plug
 	if supervisorOverride != nil {
 		options = append(options, pluginenv.SupervisorProvider(supervisorOverride))
 	} else if err := sandbox.CheckSupport(); err != nil {
-		mlog.Warn(err.Error())
-		mlog.Warn("plugin sandboxing is not supported. plugins will run with the same access level as the server. See documentation to learn more: https://developers.mattermost.com/extend/plugins/security/")
+		mlog.Warn("plugin sandboxing is not supported. plugins will run with the same access level as the server. See documentation to learn more: https://developers.mattermost.com/extend/plugins/security/", mlog.Err(err))
 		options = append(options, pluginenv.SupervisorProvider(rpcplugin.SupervisorProvider))
 	} else {
 		options = append(options, pluginenv.SupervisorProvider(sandbox.SupervisorProvider))
 	}
 
 	if env, err := pluginenv.New(options...); err != nil {
-		mlog.Error("failed to start up plugins: " + err.Error())
+		mlog.Error("Failed to start up plugins", mlog.Err(err))
 		return
 	} else {
 		a.PluginEnv = env
@@ -415,36 +416,34 @@ func (a *App) InitPlugins(pluginPath, webappPath string, supervisorOverride plug
 
 	for id, asset := range prepackagedPlugins {
 		if tarball, err := asset("plugin.tar.gz"); err != nil {
-			mlog.Error("failed to install prepackaged plugin: " + err.Error())
+			mlog.Error("Failed to install prepackaged plugin", mlog.Err(err))
 		} else if tarball != nil {
 			a.removePlugin(id, true)
 			if _, err := a.installPlugin(bytes.NewReader(tarball), true); err != nil {
-				mlog.Error("failed to install prepackaged plugin: " + err.Error())
+				mlog.Error("Failed to install prepackaged plugin", mlog.Err(err))
 			}
 			if _, ok := a.Config().PluginSettings.PluginStates[id]; !ok && id != "zoom" {
 				if err := a.EnablePlugin(id); err != nil {
-					mlog.Error("failed to enable prepackaged plugin: " + err.Error())
+					mlog.Error("Failed to enable prepackaged plugin", mlog.Err(err))
 				}
 			}
 		}
 	}
 
 	a.RemoveConfigListener(a.PluginConfigListenerId)
-	a.PluginConfigListenerId = a.AddConfigListener(func(prevCfg, cfg *model.Config) {
+	a.PluginConfigListenerId = a.AddConfigListener(func(_, cfg *model.Config) {
 		if a.PluginEnv == nil {
 			return
 		}
 
-		if *prevCfg.PluginSettings.Enable && *cfg.PluginSettings.Enable {
-			a.ActivatePlugins()
-		}
+		a.setPluginsActive(*cfg.PluginSettings.Enable)
 
 		for _, err := range a.PluginEnv.Hooks().OnConfigurationChange() {
 			mlog.Error(err.Error())
 		}
 	})
 
-	a.ActivatePlugins()
+	a.setPluginsActive(true)
 }
 
 func (a *App) ServePluginRequest(w http.ResponseWriter, r *http.Request) {