Merge pull request #5173 from hashicorp/b-log-levels

Plugins use parent loggers

CHANGELOG.md

@@ -17,6 +17,7 @@ IMPROVEMENTS:
  according to different node attributes [[GH-4512](https://github.com/hashicorp/nomad/issues/4512)]
  * core: Added support for spreading allocations across a specific attribute. Operators can specify spread
    target percentages across failure domains such as datacenter or rack [[GH-4512](https://github.com/hashicorp/nomad/issues/4512)]
+ * agent: Support JSON log output [[GH-5173](https://github.com/hashicorp/nomad/issues/5173)]
  * client: Added service metadata tag that enables the Consul UI to show a Nomad 
  icon for services registered by Nomad [[GH-4889](https://github.com/hashicorp/nomad/issues/4889)]
  * client: Refactor client to support plugins and improve state handling [[GH-4792](https://github.com/hashicorp/nomad/pull/4792)]

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

command/agent/agent.go

@@ -100,7 +100,7 @@ func NewAgent(config *Config, logOutput io.Writer, inmem *metrics.InmemSink) (*A
 		Name:       "agent",
 		Level:      log.LevelFromString(config.LogLevel),
 		Output:     logOutput,
-		JSONFormat: false, // TODO(alex,hclog) Add a config option
+		JSONFormat: config.LogJson,
 	})
 	a.httpLogger = a.logger.ResetNamed("http")
 

command/agent/command.go

@@ -109,6 +109,7 @@ func (c *Command) readConfig() *Config {
 	flags.StringVar(&cmdConfig.PluginDir, "plugin-dir", "", "")
 	flags.StringVar(&cmdConfig.Datacenter, "dc", "", "")
 	flags.StringVar(&cmdConfig.LogLevel, "log-level", "", "")
+	flags.BoolVar(&cmdConfig.LogJson, "log-json", false, "")
 	flags.StringVar(&cmdConfig.NodeName, "node", "", "")
 
 	// Consul options
@@ -494,6 +495,7 @@ func (c *Command) AutocompleteFlags() complete.Flags {
 		"-plugin-dir":                    complete.PredictDirs("*"),
 		"-dc":                            complete.PredictAnything,
 		"-log-level":                     complete.PredictAnything,
+		"-json-logs":                     complete.PredictNothing,
 		"-node":                          complete.PredictAnything,
 		"-consul-auth":                   complete.PredictAnything,
 		"-consul-auto-advertise":         complete.PredictNothing,
@@ -1127,6 +1129,9 @@ General Options (clients and servers):
     DEBUG, INFO, and WARN, in decreasing order of verbosity. The
     default is INFO.
 
+  -log-json
+    Output logs in a JSON format. The default is false.
+
   -node=<name>
     The name of the local agent. This name is used to identify the node
     in the cluster. The name must be unique per region. The default is

command/agent/config-test-fixtures/basic.hcl

@@ -4,6 +4,7 @@ name = "my-web"
 data_dir = "/tmp/nomad"
 plugin_dir = "/tmp/nomad-plugins"
 log_level = "ERR"
+log_json = true
 bind_addr = "192.168.0.1"
 enable_debug = true
 ports {

command/agent/config.go

@@ -40,9 +40,12 @@ type Config struct {
 	// PluginDir is the directory to lookup plugins.
 	PluginDir string `mapstructure:"plugin_dir"`
 
-	// LogLevel is the level of the logs to putout
+	// LogLevel is the level of the logs to put out
 	LogLevel string `mapstructure:"log_level"`
 
+	// LogJson enables log output in a JSON format
+	LogJson bool `mapstructure:"log_json"`
+
 	// BindAddr is the address on which all of nomad's services will
 	// be bound. If not specified, this defaults to 127.0.0.1.
 	BindAddr string `mapstructure:"bind_addr"`
@@ -722,6 +725,9 @@ func (c *Config) Merge(b *Config) *Config {
 	if b.LogLevel != "" {
 		result.LogLevel = b.LogLevel
 	}
+	if b.LogJson {
+		result.LogJson = true
+	}
 	if b.BindAddr != "" {
 		result.BindAddr = b.BindAddr
 	}

command/agent/config_parse.go

@@ -9,7 +9,7 @@ import (
 	"time"
 
 	multierror "github.com/hashicorp/go-multierror"
-	"github.com/hashicorp/go-version"
+	version "github.com/hashicorp/go-version"
 	"github.com/hashicorp/hcl"
 	"github.com/hashicorp/hcl/hcl/ast"
 	"github.com/hashicorp/nomad/helper"
@@ -80,6 +80,7 @@ func parseConfig(result *Config, list *ast.ObjectList) error {
 		"data_dir",
 		"plugin_dir",
 		"log_level",
+		"log_json",
 		"bind_addr",
 		"enable_debug",
 		"ports",

command/agent/config_parse_test.go

@@ -26,6 +26,7 @@ func TestConfig_Parse(t *testing.T) {
 				DataDir:     "/tmp/nomad",
 				PluginDir:   "/tmp/nomad-plugins",
 				LogLevel:    "ERR",
+				LogJson:     true,
 				BindAddr:    "192.168.0.1",
 				EnableDebug: true,
 				Ports: &Ports{

command/agent/config_test.go

@@ -47,6 +47,7 @@ func TestConfig_Merge(t *testing.T) {
 		DataDir:                   "/tmp/dir1",
 		PluginDir:                 "/tmp/pluginDir1",
 		LogLevel:                  "INFO",
+		LogJson:                   false,
 		EnableDebug:               false,
 		LeaveOnInt:                false,
 		LeaveOnTerm:               false,
@@ -193,6 +194,7 @@ func TestConfig_Merge(t *testing.T) {
 		DataDir:                   "/tmp/dir2",
 		PluginDir:                 "/tmp/pluginDir2",
 		LogLevel:                  "DEBUG",
+		LogJson:                   true,
 		EnableDebug:               true,
 		LeaveOnInt:                true,
 		LeaveOnTerm:               true,

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
 }

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
 }

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
 }

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

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()

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)
 	}

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)
 	}

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
 	}

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)
 	}