From 64dfff080a658890a4eb7924fd465e20d71c386a Mon Sep 17 00:00:00 2001 From: Peter Wilson Date: Wed, 29 Nov 2023 12:46:18 +0000 Subject: [PATCH] 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 --- changelog/24252.txt | 3 + command/agent.go | 35 +++--- .../agent/internal/ctmanager/runner_config.go | 1 - command/agent_test.go | 104 +++++++++++++++++- 4 files changed, 128 insertions(+), 15 deletions(-) create mode 100644 changelog/24252.txt diff --git a/changelog/24252.txt b/changelog/24252.txt new file mode 100644 index 0000000000..343811bfd0 --- /dev/null +++ b/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. +``` \ No newline at end of file diff --git a/command/agent.go b/command/agent.go index 220679beb3..b410da8c8a 100644 --- a/command/agent.go +++ b/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 { - return nil, errors + if errs != nil { + 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 { - return nil, errors + if errs != nil { + return nil, errs } if err := cfg.ValidateConfig(); err != nil { diff --git a/command/agent/internal/ctmanager/runner_config.go b/command/agent/internal/ctmanager/runner_config.go index 21b3bc8e82..408602998d 100644 --- a/command/agent/internal/ctmanager/runner_config.go +++ b/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" ) diff --git a/command/agent_test.go b/command/agent_test.go index d3868d43a1..3ab66b4623 100644 --- a/command/agent_test.go +++ b/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.