Fix non-JSON log messages when using -log-format JSON (#24252)

* Fix non-JSON log messages when using -log-format JSON

Removed the call to consul-template's logging.Setup inside the created of config for the Runner. Instead we call it when we assign the logger to the Agent command.

* The elusive extra line

* Adjust the approach

* changelog

* Infer levels *with* timestamp prefix

* InferLeveslWithTimestamp required InferLevels

* Test to show -log-format and -log-file working in consul-template generated messages

* classic typo

---------

Co-authored-by: Violet Hynes <violet.hynes@hashicorp.com>

changelog/24252.txt

@@ -0,0 +1,3 @@
+```release-note:bug
+agent/logging: Agent should now honor correct -log-format and -log-file settings in logs generated by the consul-template library.
+```

command/agent.go

@@ -20,7 +20,7 @@ import (
 
 	systemd "github.com/coreos/go-systemd/daemon"
 	ctconfig "github.com/hashicorp/consul-template/config"
-	log "github.com/hashicorp/go-hclog"
+	hclog "github.com/hashicorp/go-hclog"
 	"github.com/hashicorp/go-multierror"
 	"github.com/hashicorp/go-secure-stdlib/gatedwriter"
 	"github.com/hashicorp/go-secure-stdlib/parseutil"
@@ -78,7 +78,7 @@ type AgentCommand struct {
 
 	logWriter io.Writer
 	logGate   *gatedwriter.Writer
-	logger    log.Logger
+	logger    hclog.Logger
 
 	// Telemetry object
 	metricsHelper *metricsutil.MetricsHelper
@@ -210,7 +210,16 @@ func (c *AgentCommand) Run(args []string) int {
 		c.outputErrors(err)
 		return 1
 	}
+
+	// Update the logger and then base the log writer on that logger.
+	// Log writer is supplied to consul-template runners for templates and execs.
+	// We want to ensure that consul-template will honor the settings, for example
+	// if the -log-format is JSON we want JSON, not a mix of JSON and non-JSON messages.
 	c.logger = l
+	c.logWriter = l.StandardWriter(&hclog.StandardLoggerOptions{
+		InferLevels:              true,
+		InferLevelsWithTimestamp: true,
+	})
 
 	infoKeys := make([]string, 0, 10)
 	info := make(map[string]string)
@@ -1093,31 +1102,31 @@ func (c *AgentCommand) handleQuit(enabled bool) http.Handler {
 }
 
 // newLogger creates a logger based on parsed config field on the Agent Command struct.
-func (c *AgentCommand) newLogger() (log.InterceptLogger, error) {
+func (c *AgentCommand) newLogger() (hclog.InterceptLogger, error) {
 	if c.config == nil {
 		return nil, fmt.Errorf("cannot create logger, no config")
 	}
 
-	var errors error
+	var errs *multierror.Error
 
 	// Parse all the log related config
 	logLevel, err := logging.ParseLogLevel(c.config.LogLevel)
 	if err != nil {
-		errors = multierror.Append(errors, err)
+		errs = multierror.Append(errs, err)
 	}
 
 	logFormat, err := logging.ParseLogFormat(c.config.LogFormat)
 	if err != nil {
-		errors = multierror.Append(errors, err)
+		errs = multierror.Append(errs, err)
 	}
 
 	logRotateDuration, err := parseutil.ParseDurationSecond(c.config.LogRotateDuration)
 	if err != nil {
-		errors = multierror.Append(errors, err)
+		errs = multierror.Append(errs, err)
 	}
 
-	if errors != nil {
+	if errs != nil {
-		return nil, errors
+		return nil, errs
 	}
 
 	logCfg := &logging.LogConfig{
@@ -1140,20 +1149,20 @@ func (c *AgentCommand) newLogger() (log.InterceptLogger, error) {
 
 // loadConfig attempts to generate an Agent config from the file(s) specified.
 func (c *AgentCommand) loadConfig(paths []string) (*agentConfig.Config, error) {
-	var errors error
+	var errs *multierror.Error
 	cfg := agentConfig.NewConfig()
 
 	for _, configPath := range paths {
 		configFromPath, err := agentConfig.LoadConfig(configPath)
 		if err != nil {
-			errors = multierror.Append(errors, fmt.Errorf("error loading configuration from %s: %w", configPath, err))
+			errs = multierror.Append(errs, fmt.Errorf("error loading configuration from %s: %w", configPath, err))
 		} else {
 			cfg = cfg.Merge(configFromPath)
 		}
 	}
 
-	if errors != nil {
+	if errs != nil {
-		return nil, errors
+		return nil, errs
 	}
 
 	if err := cfg.ValidateConfig(); err != nil {

command/agent/internal/ctmanager/runner_config.go

@@ -11,7 +11,6 @@ import (
 	ctconfig "github.com/hashicorp/consul-template/config"
 	ctlogging "github.com/hashicorp/consul-template/logging"
 	"github.com/hashicorp/go-hclog"
-
 	"github.com/hashicorp/vault/command/agent/config"
 	"github.com/hashicorp/vault/sdk/helper/pointerutil"
 )

command/agent_test.go

@@ -4,6 +4,7 @@
 package command
 
 import (
+	"bufio"
 	"crypto/tls"
 	"crypto/x509"
 	"encoding/json"
@@ -826,7 +827,7 @@ auto_auth {
 			verify := func(suffix string) {
 				t.Helper()
 				// We need to poll for a bit to give Agent time to render the
-				// templates. Without this this, the test will attempt to read
+				// templates. Without this, the test will attempt to read
 				// the temp dir before Agent has had time to render and will
 				// likely fail the test
 				tick := time.Tick(1 * time.Second)
@@ -3070,6 +3071,107 @@ vault {
 	}
 }
 
+// TestAgent_Logging_ConsulTemplate attempts to ensure two things about Vault Agent logs:
+// 1. When -log-format command line arg is set to JSON, it is honored as the output format
+// for messages generated from within the consul-template library.
+// 2. When -log-file command line arg is supplied, a file receives all log messages
+// generated by the consul-template library (they don't just go to stdout/stderr).
+// Should prevent a regression of: https://github.com/hashicorp/vault/issues/21109
+func TestAgent_Logging_ConsulTemplate(t *testing.T) {
+	const (
+		runnerLogMessage = "(runner) creating new runner (dry: false, once: false)"
+	)
+
+	// Configure a Vault server so Agent can successfully communicate and render its templates
+	cluster := minimal.NewTestSoloCluster(t, nil)
+	apiClient := cluster.Cores[0].Client
+	t.Setenv(api.EnvVaultAddress, apiClient.Address())
+	tempDir := t.TempDir()
+	roleIDPath, secretIDPath := setupAppRoleAndKVMounts(t, apiClient)
+
+	// Create relevant configs for Vault Agent (config, template config)
+	templateSrc := filepath.Join(tempDir, "render_1.tmpl")
+	err := os.WriteFile(templateSrc, []byte(templateContents(1)), 0o600)
+	require.NoError(t, err)
+	templateConfig := fmt.Sprintf(templateConfigString, templateSrc, tempDir, "render_1.json")
+
+	config := `
+vault {
+  address = "%s"
+	tls_skip_verify = true
+}
+
+auto_auth {
+    method "approle" {
+        mount_path = "auth/approle"
+        config = {
+            role_id_file_path = "%s"
+            secret_id_file_path = "%s"
+            remove_secret_id_file_after_reading = false
+        }
+    }
+}
+
+%s
+`
+	config = fmt.Sprintf(config, apiClient.Address(), roleIDPath, secretIDPath, templateConfig)
+	configFileName := filepath.Join(tempDir, "config.hcl")
+	err = os.WriteFile(configFileName, []byte(config), 0o600)
+	require.NoError(t, err)
+	_, cmd := testAgentCommand(t, nil)
+	logFilePath := filepath.Join(tempDir, "agent")
+
+	// Start Vault Agent
+	go func() {
+		code := cmd.Run([]string{"-config", configFileName, "-log-format", "json", "-log-file", logFilePath, "-log-level", "trace"})
+		require.Equalf(t, 0, code, "Vault Agent returned a non-zero exit code")
+	}()
+
+	select {
+	case <-cmd.startedCh:
+	case <-time.After(5 * time.Second):
+		t.Fatal("timeout starting agent")
+	}
+
+	// Give Vault Agent some time to render our template.
+	time.Sleep(3 * time.Second)
+
+	// This flag will be used to capture whether we saw a consul-template log
+	// message in the log file (the presence of the log file is also part of the test)
+	found := false
+
+	// Vault Agent file logs will match agent-{timestamp}.log based on the
+	// cmd line argument we supplied, e.g. agent-1701258869573205000.log
+	m, err := filepath.Glob(logFilePath + "*")
+	require.NoError(t, err)
+	require.Truef(t, len(m) > 0, "no files were found")
+
+	for _, p := range m {
+		f, err := os.Open(p)
+		require.NoError(t, err)
+
+		fs := bufio.NewScanner(f)
+		fs.Split(bufio.ScanLines)
+
+		for fs.Scan() {
+			s := fs.Text()
+			entry := make(map[string]string)
+			err := json.Unmarshal([]byte(s), &entry)
+			require.NoError(t, err)
+			v, ok := entry["@message"]
+			if !ok {
+				continue
+			}
+			if v == runnerLogMessage {
+				found = true
+				break
+			}
+		}
+	}
+
+	require.Truef(t, found, "unable to find consul-template partial message in logs", runnerLogMessage)
+}
+
 // Get a randomly assigned port and then free it again before returning it.
 // There is still a race when trying to use it, but should work better
 // than a static port.