From 270ae48b824e4d77ef98d23ae43accff01da0429 Mon Sep 17 00:00:00 2001 From: Alex Dadgar Date: Wed, 9 Jan 2019 15:06:58 -0800 Subject: [PATCH] Plugins use parent loggers This PR fixes various instances of plugins being launched without using the parent loggers. This meant that logs would not all go to the same output, break formatting etc. --- client/gc.go | 2 +- command/docker_logger_plugin.go | 11 ++++++-- command/executor_plugin.go | 22 ++++++++++++--- command/logmon_plugin.go | 1 + demo/vagrant/client1.hcl | 6 +++++ drivers/docker/cmd/main.go | 9 ++++++- drivers/docker/docklog/plugin.go | 1 + drivers/exec/driver.go | 13 ++++----- drivers/java/driver.go | 14 +++++----- drivers/qemu/driver.go | 15 +++++------ drivers/rawexec/driver.go | 12 ++++----- drivers/shared/executor/executor.go | 4 +-- drivers/shared/executor/executor_linux.go | 2 +- drivers/shared/executor/executor_windows.go | 2 +- drivers/shared/executor/plugins.go | 17 ++++-------- drivers/shared/executor/utils.go | 30 +++++++++++---------- 16 files changed, 92 insertions(+), 69 deletions(-) diff --git a/client/gc.go b/client/gc.go index 2ec640d08..07ff4e7c0 100644 --- a/client/gc.go +++ b/client/gc.go @@ -187,7 +187,7 @@ func (a *AllocGarbageCollector) destroyAllocRunner(allocID string, ar AllocRunne case <-a.shutdownCh: } - a.logger.Debug("garbage collected %s", "alloc_id", allocID) + a.logger.Debug("alloc garbage collected", "alloc_id", allocID) // Release the lock <-a.destroyCh diff --git a/command/docker_logger_plugin.go b/command/docker_logger_plugin.go index 4b79fa4a4..707def19f 100644 --- a/command/docker_logger_plugin.go +++ b/command/docker_logger_plugin.go @@ -3,7 +3,7 @@ package command import ( "strings" - hclog "github.com/hashicorp/go-hclog" + log "github.com/hashicorp/go-hclog" plugin "github.com/hashicorp/go-plugin" "github.com/hashicorp/nomad/drivers/docker/docklog" "github.com/hashicorp/nomad/plugins/base" @@ -25,12 +25,19 @@ func (e *DockerLoggerPluginCommand) Synopsis() string { } func (e *DockerLoggerPluginCommand) Run(args []string) int { + logger := log.New(&log.LoggerOptions{ + Level: log.Trace, + JSONFormat: true, + Name: docklog.PluginName, + }) + plugin.Serve(&plugin.ServeConfig{ HandshakeConfig: base.Handshake, Plugins: map[string]plugin.Plugin{ - docklog.PluginName: docklog.NewPlugin(docklog.NewDockerLogger(hclog.Default().Named(docklog.PluginName))), + docklog.PluginName: docklog.NewPlugin(docklog.NewDockerLogger(logger)), }, GRPCServer: plugin.DefaultGRPCServer, + Logger: logger, }) return 0 } diff --git a/command/executor_plugin.go b/command/executor_plugin.go index 7e7522bc5..9bde337ad 100644 --- a/command/executor_plugin.go +++ b/command/executor_plugin.go @@ -2,10 +2,12 @@ package command import ( "encoding/json" + "io" "os" "strings" hclog "github.com/hashicorp/go-hclog" + log "github.com/hashicorp/go-hclog" plugin "github.com/hashicorp/go-plugin" "github.com/hashicorp/nomad/drivers/shared/executor" @@ -32,24 +34,38 @@ func (e *ExecutorPluginCommand) Run(args []string) int { e.Ui.Error("json configuration not provided") return 1 } + config := args[0] var executorConfig executor.ExecutorConfig if err := json.Unmarshal([]byte(config), &executorConfig); err != nil { return 1 } - stdo, err := os.OpenFile(executorConfig.LogFile, os.O_CREATE|os.O_RDWR|os.O_APPEND, 0666) + + f, err := os.OpenFile(executorConfig.LogFile, os.O_CREATE|os.O_RDWR|os.O_APPEND, 0666) if err != nil { e.Ui.Error(err.Error()) return 1 } + + // Tee the logs to stderr and the file so that they are streamed to the + // client + out := io.MultiWriter(f, os.Stderr) + + // Create the logger + logger := log.New(&log.LoggerOptions{ + Level: hclog.LevelFromString(executorConfig.LogLevel), + JSONFormat: true, + Output: out, + }) + plugin.Serve(&plugin.ServeConfig{ HandshakeConfig: base.Handshake, Plugins: executor.GetPluginMap( - stdo, - hclog.LevelFromString(executorConfig.LogLevel), + logger, executorConfig.FSIsolation, ), GRPCServer: plugin.DefaultGRPCServer, + Logger: logger, }) return 0 } diff --git a/command/logmon_plugin.go b/command/logmon_plugin.go index 57d7eb8c4..4d3bda20c 100644 --- a/command/logmon_plugin.go +++ b/command/logmon_plugin.go @@ -36,6 +36,7 @@ func (e *LogMonPluginCommand) Run(args []string) int { "logmon": logmon.NewPlugin(logmon.NewLogMon(logger)), }, GRPCServer: plugin.DefaultGRPCServer, + Logger: logger, }) return 0 } diff --git a/demo/vagrant/client1.hcl b/demo/vagrant/client1.hcl index 6ba1e5fc9..c2ec49261 100644 --- a/demo/vagrant/client1.hcl +++ b/demo/vagrant/client1.hcl @@ -21,3 +21,9 @@ client { ports { http = 5656 } + +plugin "raw_exec" { + config { + enabled = true + } +} diff --git a/drivers/docker/cmd/main.go b/drivers/docker/cmd/main.go index e0f898f3a..faa77e5f6 100644 --- a/drivers/docker/cmd/main.go +++ b/drivers/docker/cmd/main.go @@ -22,12 +22,19 @@ func main() { // Detect if we are being launched as a docker logging plugin switch os.Args[1] { case docklog.PluginName: + logger := log.New(&log.LoggerOptions{ + Level: log.Trace, + JSONFormat: true, + Name: docklog.PluginName, + }) + plugin.Serve(&plugin.ServeConfig{ HandshakeConfig: base.Handshake, Plugins: map[string]plugin.Plugin{ - docklog.PluginName: docklog.NewPlugin(docklog.NewDockerLogger(log.Default().Named(docklog.PluginName))), + docklog.PluginName: docklog.NewPlugin(docklog.NewDockerLogger(logger)), }, GRPCServer: plugin.DefaultGRPCServer, + Logger: logger, }) return diff --git a/drivers/docker/docklog/plugin.go b/drivers/docker/docklog/plugin.go index bc81d0ce7..967eeb9ca 100644 --- a/drivers/docker/docklog/plugin.go +++ b/drivers/docker/docklog/plugin.go @@ -31,6 +31,7 @@ func LaunchDockerLogger(logger hclog.Logger) (DockerLogger, *plugin.Client, erro AllowedProtocols: []plugin.Protocol{ plugin.ProtocolGRPC, }, + Logger: logger, }) rpcClient, err := client.Client() diff --git a/drivers/exec/driver.go b/drivers/exec/driver.go index 069d27fa8..19640ed63 100644 --- a/drivers/exec/driver.go +++ b/drivers/exec/driver.go @@ -10,7 +10,6 @@ import ( "github.com/hashicorp/consul-template/signals" hclog "github.com/hashicorp/go-hclog" - plugin "github.com/hashicorp/go-plugin" "github.com/hashicorp/nomad/client/fingerprint" "github.com/hashicorp/nomad/drivers/shared/eventer" "github.com/hashicorp/nomad/drivers/shared/executor" @@ -242,11 +241,8 @@ func (d *Driver) RecoverTask(handle *drivers.TaskHandle) error { return fmt.Errorf("failed to build ReattachConfig from task state: %v", err) } - pluginConfig := &plugin.ClientConfig{ - Reattach: plugRC, - } - - exec, pluginClient, err := executor.CreateExecutorWithConfig(pluginConfig, os.Stderr) + exec, pluginClient, err := executor.CreateExecutorWithConfig(plugRC, + d.logger.With("task_name", handle.Config.Name, "alloc_id", handle.Config.AllocID)) if err != nil { d.logger.Error("failed to reattach to executor", "error", err, "task_id", handle.Config.ID) return fmt.Errorf("failed to reattach to executor: %v", err) @@ -289,8 +285,9 @@ func (d *Driver) StartTask(cfg *drivers.TaskConfig) (*drivers.TaskHandle, *drive FSIsolation: true, } - // TODO: best way to pass port ranges in from client config - exec, pluginClient, err := executor.CreateExecutor(os.Stderr, hclog.Debug, d.nomadConfig, executorConfig) + exec, pluginClient, err := executor.CreateExecutor( + d.logger.With("task_name", handle.Config.Name, "alloc_id", handle.Config.AllocID), + d.nomadConfig, executorConfig) if err != nil { return nil, nil, fmt.Errorf("failed to create executor: %v", err) } diff --git a/drivers/java/driver.go b/drivers/java/driver.go index 9cd42d3eb..27f8ce875 100644 --- a/drivers/java/driver.go +++ b/drivers/java/driver.go @@ -10,8 +10,7 @@ import ( "time" "github.com/hashicorp/consul-template/signals" - "github.com/hashicorp/go-hclog" - "github.com/hashicorp/go-plugin" + hclog "github.com/hashicorp/go-hclog" "github.com/hashicorp/nomad/client/fingerprint" "github.com/hashicorp/nomad/drivers/shared/eventer" "github.com/hashicorp/nomad/drivers/shared/executor" @@ -264,11 +263,8 @@ func (d *Driver) RecoverTask(handle *drivers.TaskHandle) error { return fmt.Errorf("failed to build ReattachConfig from taskConfig state: %v", err) } - pluginConfig := &plugin.ClientConfig{ - Reattach: plugRC, - } - - execImpl, pluginClient, err := executor.CreateExecutorWithConfig(pluginConfig, os.Stderr) + execImpl, pluginClient, err := executor.CreateExecutorWithConfig(plugRC, + d.logger.With("task_name", handle.Config.Name, "alloc_id", handle.Config.AllocID)) if err != nil { d.logger.Error("failed to reattach to executor", "error", err, "task_id", handle.Config.ID) return fmt.Errorf("failed to reattach to executor: %v", err) @@ -323,7 +319,9 @@ func (d *Driver) StartTask(cfg *drivers.TaskConfig) (*drivers.TaskHandle, *drive FSIsolation: capabilities.FSIsolation == drivers.FSIsolationChroot, } - exec, pluginClient, err := executor.CreateExecutor(os.Stderr, hclog.Debug, d.nomadConfig, executorConfig) + exec, pluginClient, err := executor.CreateExecutor( + d.logger.With("task_name", handle.Config.Name, "alloc_id", handle.Config.AllocID), + d.nomadConfig, executorConfig) if err != nil { return nil, nil, fmt.Errorf("failed to create executor: %v", err) } diff --git a/drivers/qemu/driver.go b/drivers/qemu/driver.go index 251615a6d..06fcb9c2c 100644 --- a/drivers/qemu/driver.go +++ b/drivers/qemu/driver.go @@ -5,7 +5,6 @@ import ( "errors" "fmt" "net" - "os" "os/exec" "path/filepath" "regexp" @@ -14,8 +13,7 @@ import ( "time" "github.com/coreos/go-semver/semver" - "github.com/hashicorp/go-hclog" - "github.com/hashicorp/go-plugin" + hclog "github.com/hashicorp/go-hclog" "github.com/hashicorp/nomad/drivers/shared/eventer" "github.com/hashicorp/nomad/drivers/shared/executor" "github.com/hashicorp/nomad/plugins/base" @@ -263,11 +261,8 @@ func (d *Driver) RecoverTask(handle *drivers.TaskHandle) error { return fmt.Errorf("failed to build ReattachConfig from taskConfig state: %v", err) } - pluginConfig := &plugin.ClientConfig{ - Reattach: plugRC, - } - - execImpl, pluginClient, err := executor.CreateExecutorWithConfig(pluginConfig, os.Stderr) + execImpl, pluginClient, err := executor.CreateExecutorWithConfig(plugRC, + d.logger.With("task_name", handle.Config.Name, "alloc_id", handle.Config.AllocID)) if err != nil { d.logger.Error("failed to reattach to executor", "error", err, "task_id", handle.Config.ID) return fmt.Errorf("failed to reattach to executor: %v", err) @@ -417,7 +412,9 @@ func (d *Driver) StartTask(cfg *drivers.TaskConfig) (*drivers.TaskHandle, *drive LogLevel: "debug", } - execImpl, pluginClient, err := executor.CreateExecutor(os.Stderr, hclog.Debug, d.nomadConfig, executorConfig) + execImpl, pluginClient, err := executor.CreateExecutor( + d.logger.With("task_name", handle.Config.Name, "alloc_id", handle.Config.AllocID), + d.nomadConfig, executorConfig) if err != nil { return nil, nil, err } diff --git a/drivers/rawexec/driver.go b/drivers/rawexec/driver.go index fc0b4c00f..3ab3ee57e 100644 --- a/drivers/rawexec/driver.go +++ b/drivers/rawexec/driver.go @@ -12,7 +12,6 @@ import ( "github.com/hashicorp/consul-template/signals" hclog "github.com/hashicorp/go-hclog" - plugin "github.com/hashicorp/go-plugin" "github.com/hashicorp/nomad/drivers/shared/eventer" "github.com/hashicorp/nomad/drivers/shared/executor" "github.com/hashicorp/nomad/plugins/base" @@ -269,12 +268,9 @@ func (d *Driver) RecoverTask(handle *drivers.TaskHandle) error { return fmt.Errorf("failed to build ReattachConfig from task state: %v", err) } - pluginConfig := &plugin.ClientConfig{ - Reattach: plugRC, - } - // Create client for reattached executor - exec, pluginClient, err := executor.CreateExecutorWithConfig(pluginConfig, os.Stderr) + exec, pluginClient, err := executor.CreateExecutorWithConfig(plugRC, + d.logger.With("task_name", handle.Config.Name, "alloc_id", handle.Config.AllocID)) if err != nil { d.logger.Error("failed to reattach to executor", "error", err, "task_id", handle.Config.ID) return fmt.Errorf("failed to reattach to executor: %v", err) @@ -316,7 +312,9 @@ func (d *Driver) StartTask(cfg *drivers.TaskConfig) (*drivers.TaskHandle, *drive LogLevel: "debug", } - exec, pluginClient, err := executor.CreateExecutor(os.Stderr, hclog.Debug, d.nomadConfig, executorConfig) + exec, pluginClient, err := executor.CreateExecutor( + d.logger.With("task_name", handle.Config.Name, "alloc_id", handle.Config.AllocID), + d.nomadConfig, executorConfig) if err != nil { return nil, nil, fmt.Errorf("failed to create executor: %v", err) } diff --git a/drivers/shared/executor/executor.go b/drivers/shared/executor/executor.go index f9576e738..39dfef1ce 100644 --- a/drivers/shared/executor/executor.go +++ b/drivers/shared/executor/executor.go @@ -248,7 +248,7 @@ func (e *UniversalExecutor) Version() (*ExecutorVersion, error) { // Launch launches the main process and returns its state. It also // configures an applies isolation on certain platforms. func (e *UniversalExecutor) Launch(command *ExecCommand) (*ProcessState, error) { - e.logger.Info("launching command", "command", command.Cmd, "args", strings.Join(command.Args, " ")) + e.logger.Debug("launching command", "command", command.Cmd, "args", strings.Join(command.Args, " ")) e.commandCfg = command @@ -419,7 +419,7 @@ var ( // Exit cleans up the alloc directory, destroys resource container and kills the // user process func (e *UniversalExecutor) Shutdown(signal string, grace time.Duration) error { - e.logger.Info("shutdown requested", "signal", signal, "grace_period_ms", grace.Round(time.Millisecond)) + e.logger.Debug("shutdown requested", "signal", signal, "grace_period_ms", grace.Round(time.Millisecond)) var merr multierror.Error // If the executor did not launch a process, return. diff --git a/drivers/shared/executor/executor_linux.go b/drivers/shared/executor/executor_linux.go index 66795377f..c359b605f 100644 --- a/drivers/shared/executor/executor_linux.go +++ b/drivers/shared/executor/executor_linux.go @@ -95,7 +95,7 @@ func NewExecutorWithIsolation(logger hclog.Logger) Executor { // Launch creates a new container in libcontainer and starts a new process with it func (l *LibcontainerExecutor) Launch(command *ExecCommand) (*ProcessState, error) { - l.logger.Info("launching command", "command", command.Cmd, "args", strings.Join(command.Args, " ")) + l.logger.Debug("launching command", "command", command.Cmd, "args", strings.Join(command.Args, " ")) // Find the nomad executable to launch the executor process with bin, err := discover.NomadExecutable() if err != nil { diff --git a/drivers/shared/executor/executor_windows.go b/drivers/shared/executor/executor_windows.go index f7e05b8fa..9d0b14070 100644 --- a/drivers/shared/executor/executor_windows.go +++ b/drivers/shared/executor/executor_windows.go @@ -63,7 +63,7 @@ func (e *UniversalExecutor) shutdownProcess(_ os.Signal, proc *os.Process) error if err := sendCtrlBreak(proc.Pid); err != nil { return fmt.Errorf("executor shutdown error: %v", err) } - e.logger.Info("sent Ctrl-Break to process", "pid", proc.Pid) + e.logger.Debug("sent Ctrl-Break to process", "pid", proc.Pid) return nil } diff --git a/drivers/shared/executor/plugins.go b/drivers/shared/executor/plugins.go index 55441e702..0e3b977e9 100644 --- a/drivers/shared/executor/plugins.go +++ b/drivers/shared/executor/plugins.go @@ -1,7 +1,6 @@ package executor import ( - "io" "net" hclog "github.com/hashicorp/go-hclog" @@ -22,18 +21,12 @@ type ExecutorConfig struct { FSIsolation bool } -func GetPluginMap(w io.Writer, logLevel hclog.Level, fsIsolation bool) map[string]plugin.Plugin { - e := new(ExecutorPlugin) - - e.logger = hclog.New(&hclog.LoggerOptions{ - Output: w, - Level: logLevel, - }) - - e.fsIsolation = fsIsolation - +func GetPluginMap(logger hclog.Logger, fsIsolation bool) map[string]plugin.Plugin { return map[string]plugin.Plugin{ - "executor": e, + "executor": &ExecutorPlugin{ + logger: logger, + fsIsolation: fsIsolation, + }, } } diff --git a/drivers/shared/executor/utils.go b/drivers/shared/executor/utils.go index c23c9d3b8..58c613223 100644 --- a/drivers/shared/executor/utils.go +++ b/drivers/shared/executor/utils.go @@ -3,7 +3,6 @@ package executor import ( "encoding/json" "fmt" - "io" "os/exec" "github.com/golang/protobuf/ptypes" @@ -26,7 +25,7 @@ const ( // CreateExecutor launches an executor plugin and returns an instance of the // Executor interface -func CreateExecutor(w io.Writer, level hclog.Level, driverConfig *base.ClientDriverConfig, +func CreateExecutor(logger hclog.Logger, driverConfig *base.ClientDriverConfig, executorConfig *ExecutorConfig) (Executor, *plugin.Client, error) { c, err := json.Marshal(executorConfig) @@ -39,11 +38,12 @@ func CreateExecutor(w io.Writer, level hclog.Level, driverConfig *base.ClientDri } config := &plugin.ClientConfig{ - Cmd: exec.Command(bin, "executor", string(c)), + HandshakeConfig: base.Handshake, + Plugins: map[string]plugin.Plugin{"executor": &ExecutorPlugin{}}, + Cmd: exec.Command(bin, "executor", string(c)), + AllowedProtocols: []plugin.Protocol{plugin.ProtocolGRPC}, + Logger: logger.Named("executor"), } - config.HandshakeConfig = base.Handshake - config.Plugins = GetPluginMap(w, level, executorConfig.FSIsolation) - config.AllowedProtocols = []plugin.Protocol{plugin.ProtocolGRPC} if driverConfig != nil { config.MaxPort = driverConfig.ClientMaxPort @@ -74,15 +74,17 @@ func CreateExecutor(w io.Writer, level hclog.Level, driverConfig *base.ClientDri } // CreateExecutorWithConfig launches a plugin with a given plugin config -func CreateExecutorWithConfig(config *plugin.ClientConfig, w io.Writer) (Executor, *plugin.Client, error) { - config.HandshakeConfig = base.Handshake +func CreateExecutorWithConfig(reattachConfig *plugin.ReattachConfig, logger hclog.Logger) (Executor, *plugin.Client, error) { + config := &plugin.ClientConfig{ + HandshakeConfig: base.Handshake, + Reattach: reattachConfig, + Plugins: map[string]plugin.Plugin{"executor": &ExecutorPlugin{}}, - // Setting this to DEBUG since the log level at the executor server process - // is already set, and this effects only the executor client. - // TODO: Use versioned plugin map to support backwards compatibility with - // existing pre-0.9 executors - config.Plugins = GetPluginMap(w, hclog.Debug, false) - config.AllowedProtocols = []plugin.Protocol{plugin.ProtocolGRPC} + // TODO: Use versioned plugin map to support backwards compatibility with + // existing pre-0.9 executors + AllowedProtocols: []plugin.Protocol{plugin.ProtocolGRPC}, + Logger: logger.Named("executor"), + } executorClient := plugin.NewClient(config) rpcClient, err := executorClient.Client()