From 0026788d4b6cc68b08567ae9fa1a98f6c89b0664 Mon Sep 17 00:00:00 2001 From: davidadeleon <56207066+davidadeleon@users.noreply.github.com> Date: Tue, 24 May 2022 13:10:53 -0400 Subject: [PATCH] api/monitor: Adding log format to monitor command and debug (#15536) * Correct handling of "unspecified" log level * Setting log-format default on monitor path * Create changelog file * Update website/content/api-docs/system/monitor.mdx Co-authored-by: Chris Capurso <1036769+ccapurso@users.noreply.github.com> Co-authored-by: Chris Capurso <1036769+ccapurso@users.noreply.github.com> --- api/sys_monitor.go | 10 ++++- changelog/15536.txt | 7 ++++ command/debug.go | 15 ++++++- command/monitor.go | 19 ++++++++- helper/monitor/monitor_test.go | 41 +++++++++++++++++++ http/sys_monitor_test.go | 44 ++++++++++++++++++++- vault/logical_system.go | 10 ++++- vault/logical_system_paths.go | 6 +++ website/content/api-docs/system/monitor.mdx | 3 ++ website/content/docs/commands/debug.mdx | 4 ++ website/content/docs/commands/monitor.mdx | 4 ++ 11 files changed, 156 insertions(+), 7 deletions(-) create mode 100644 changelog/15536.txt diff --git a/api/sys_monitor.go b/api/sys_monitor.go index df2774672..6813799f0 100644 --- a/api/sys_monitor.go +++ b/api/sys_monitor.go @@ -5,11 +5,13 @@ import ( "context" "fmt" "net/http" + + "github.com/hashicorp/vault/sdk/helper/logging" ) // Monitor returns a channel that outputs strings containing the log messages // coming from the server. -func (c *Sys) Monitor(ctx context.Context, logLevel string) (chan string, error) { +func (c *Sys) Monitor(ctx context.Context, logLevel string, logFormat string) (chan string, error) { r := c.c.NewRequest(http.MethodGet, "/v1/sys/monitor") if logLevel == "" { @@ -18,6 +20,12 @@ func (c *Sys) Monitor(ctx context.Context, logLevel string) (chan string, error) r.Params.Add("log_level", logLevel) } + if logFormat == "" || logFormat == logging.UnspecifiedFormat.String() { + r.Params.Add("log_format", "standard") + } else { + r.Params.Add("log_format", logFormat) + } + resp, err := c.c.RawRequestWithContext(ctx, r) if err != nil { return nil, err diff --git a/changelog/15536.txt b/changelog/15536.txt new file mode 100644 index 000000000..7bda61919 --- /dev/null +++ b/changelog/15536.txt @@ -0,0 +1,7 @@ +```release-note:improvement +api/monitor: Add log_format option to allow for logs to be emitted in JSON format +``` + +```release-note:improvement +command/debug: Add log_format flag to allow for logs to be emitted in JSON format +``` diff --git a/command/debug.go b/command/debug.go index e46aa2cef..0dd0fbf13 100644 --- a/command/debug.go +++ b/command/debug.go @@ -93,6 +93,9 @@ type DebugCommand struct { flagOutput string flagTargets []string + // logFormat defines the output format for Monitor + logFormat string + // debugIndex is used to keep track of the index state, which gets written // to a file at the end. debugIndex *debugIndex @@ -180,6 +183,14 @@ func (c *DebugCommand) Flags() *FlagSets { "replication-status, server-status, log.", }) + f.StringVar(&StringVar{ + Name: "log-format", + Target: &c.logFormat, + Default: "standard", + Usage: "Log format to be captured if \"log\" target specified. " + + "Supported values are \"standard\" and \"json\". The default is \"standard\".", + }) + return set } @@ -1053,14 +1064,14 @@ func (c *DebugCommand) captureError(target string, err error) { } func (c *DebugCommand) writeLogs(ctx context.Context) { - out, err := os.OpenFile(filepath.Join(c.flagOutput, "vault.log"), os.O_CREATE, 0o600) + out, err := os.OpenFile(filepath.Join(c.flagOutput, "vault.log"), os.O_CREATE|os.O_WRONLY, 0o600) if err != nil { c.captureError("log", err) return } defer out.Close() - logCh, err := c.cachedClient.Sys().Monitor(ctx, "trace") + logCh, err := c.cachedClient.Sys().Monitor(ctx, "trace", c.logFormat) if err != nil { c.captureError("log", err) return diff --git a/command/monitor.go b/command/monitor.go index 3a87d5af3..e63092589 100644 --- a/command/monitor.go +++ b/command/monitor.go @@ -18,7 +18,8 @@ var ( type MonitorCommand struct { *BaseCommand - logLevel string + logLevel string + logFormat string // ShutdownCh is used to capture interrupt signal and end streaming ShutdownCh chan struct{} @@ -55,6 +56,13 @@ func (c *MonitorCommand) Flags() *FlagSets { "(in order of detail) are \"trace\", \"debug\", \"info\", \"warn\"" + " and \"error\". These are not case sensitive.", }) + f.StringVar(&StringVar{ + Name: "log-format", + Target: &c.logFormat, + Default: "standard", + Completion: complete.PredictSet("standard", "json"), + Usage: "Output format of logs. Supported values are \"standard\" and \"json\".", + }) return set } @@ -88,6 +96,13 @@ func (c *MonitorCommand) Run(args []string) int { return 1 } + c.logFormat = strings.ToLower(c.logFormat) + validFormats := []string{"standard", "json"} + if !strutil.StrListContains(validFormats, c.logFormat) { + c.UI.Error(fmt.Sprintf("%s is an unknown log format. Valid log formats are: %s", c.logFormat, validFormats)) + return 1 + } + client, err := c.Client() if err != nil { c.UI.Error(err.Error()) @@ -100,7 +115,7 @@ func (c *MonitorCommand) Run(args []string) int { var logCh chan string ctx, cancel := context.WithCancel(context.Background()) defer cancel() - logCh, err = client.Sys().Monitor(ctx, c.logLevel) + logCh, err = client.Sys().Monitor(ctx, c.logLevel, c.logFormat) if err != nil { c.UI.Error(fmt.Sprintf("Error starting monitor: %s", err)) return 1 diff --git a/helper/monitor/monitor_test.go b/helper/monitor/monitor_test.go index 7ae7a0fe8..0133a351b 100644 --- a/helper/monitor/monitor_test.go +++ b/helper/monitor/monitor_test.go @@ -1,6 +1,7 @@ package monitor import ( + "encoding/json" "fmt" "strings" "testing" @@ -38,6 +39,46 @@ func TestMonitor_Start(t *testing.T) { } } +func TestMonitor_JSONFormat(t *testing.T) { + t.Parallel() + + logger := log.NewInterceptLogger(&log.LoggerOptions{ + Level: log.Error, + }) + + m, _ := NewMonitor(512, logger, &log.LoggerOptions{ + Level: log.Debug, + JSONFormat: true, + }) + + type jsonlog struct { + Level string `json:"@level"` + Message string `json:"@message"` + TimeStamp string `json:"@timestamp"` + } + jsonLog := &jsonlog{} + + logCh := m.Start() + defer m.Stop() + + go func() { + logger.Debug("test json log") + time.Sleep(10 * time.Millisecond) + }() + + select { + case l := <-logCh: + err := json.Unmarshal(l, jsonLog) + if err != nil { + t.Fatal("Expected JSON log from channel") + } + require.Contains(t, jsonLog.Message, "test json log") + return + case <-time.After(5 * time.Second): + t.Fatal("Expected to receive from log channel") + } +} + func TestMonitor_Start_Unbuffered(t *testing.T) { t.Parallel() diff --git a/http/sys_monitor_test.go b/http/sys_monitor_test.go index f687ab209..733862ec4 100644 --- a/http/sys_monitor_test.go +++ b/http/sys_monitor_test.go @@ -2,6 +2,7 @@ package http import ( "context" + "encoding/json" "strings" "testing" "time" @@ -35,6 +36,29 @@ func TestSysMonitorUnknownLogLevel(t *testing.T) { } } +func TestSysMonitorUnknownLogFormat(t *testing.T) { + cluster := vault.NewTestCluster(t, nil, &vault.TestClusterOptions{HandlerFunc: Handler}) + cluster.Start() + defer cluster.Cleanup() + + client := cluster.Cores[0].Client + request := client.NewRequest("GET", "/v1/sys/monitor") + request.Params.Add("log_format", "haha") + _, err := client.RawRequest(request) + + if err == nil { + t.Fatal("expected to get an error, but didn't") + } else { + if !strings.Contains(err.Error(), "Code: 400") { + t.Fatalf("expected to receive a 400 error, but got %s instead", err) + } + + if !strings.Contains(err.Error(), "unknown log format") { + t.Fatalf("expected to receive a message indicating an unknown log format, but got %s instead", err) + } + } +} + func TestSysMonitorStreamingLogs(t *testing.T) { logger := log.NewInterceptLogger(&log.LoggerOptions{ Output: log.DefaultOutput, @@ -42,6 +66,8 @@ func TestSysMonitorStreamingLogs(t *testing.T) { JSONFormat: logging.ParseEnvLogFormat() == logging.JSONFormat, }) + lf := logging.ParseEnvLogFormat().String() + cluster := vault.NewTestCluster(t, nil, &vault.TestClusterOptions{HandlerFunc: Handler, Logger: logger}) cluster.Start() defer cluster.Cleanup() @@ -52,16 +78,32 @@ func TestSysMonitorStreamingLogs(t *testing.T) { debugCount := 0 ctx, cancel := context.WithTimeout(context.Background(), 90*time.Second) defer cancel() - logCh, err := client.Sys().Monitor(ctx, "DEBUG") + logCh, err := client.Sys().Monitor(ctx, "DEBUG", lf) if err != nil { t.Fatal(err) } + type jsonlog struct { + Level string `json:"@level"` + Message string `json:"@message"` + TimeStamp string `json:"@timestamp"` + } + jsonLog := &jsonlog{} + timeCh := time.After(5 * time.Second) for { select { case log := <-logCh: + if lf == "json" { + err := json.Unmarshal([]byte(log), jsonLog) + if err != nil { + t.Fatal("Expected JSON log from channel") + } + if strings.Contains(jsonLog.Level, "debug") { + debugCount++ + } + } if strings.Contains(log, "[DEBUG]") { debugCount++ } diff --git a/vault/logical_system.go b/vault/logical_system.go index 6c9644789..ec59e3858 100644 --- a/vault/logical_system.go +++ b/vault/logical_system.go @@ -3244,6 +3244,14 @@ func (b *SystemBackend) handleMonitor(ctx context.Context, req *logical.Request, return logical.ErrorResponse("unknown log level"), nil } + lf := data.Get("log_format").(string) + lowerLogFormat := strings.ToLower(lf) + + validFormats := []string{"standard", "json"} + if !strutil.StrListContains(validFormats, lowerLogFormat) { + return logical.ErrorResponse("unknown log format"), nil + } + flusher, ok := w.ResponseWriter.(http.Flusher) if !ok { // http.ResponseWriter is wrapped in wrapGenericHandler, so let's @@ -3258,7 +3266,7 @@ func (b *SystemBackend) handleMonitor(ctx context.Context, req *logical.Request, } } - isJson := b.Core.LogFormat() == "json" + isJson := b.Core.LogFormat() == "json" || lf == "json" logger := b.Core.Logger().(log.InterceptLogger) mon, err := monitor.NewMonitor(512, logger, &log.LoggerOptions{ diff --git a/vault/logical_system_paths.go b/vault/logical_system_paths.go index c6d36b431..82129c92b 100644 --- a/vault/logical_system_paths.go +++ b/vault/logical_system_paths.go @@ -1388,6 +1388,12 @@ func (b *SystemBackend) monitorPath() *framework.Path { Description: "Log level to view system logs at. Currently supported values are \"trace\", \"debug\", \"info\", \"warn\", \"error\".", Query: true, }, + "log_format": { + Type: framework.TypeString, + Description: "Output format of logs. Supported values are \"standard\" and \"json\". The default is \"standard\".", + Query: true, + Default: "standard", + }, }, Callbacks: map[logical.Operation]framework.OperationFunc{ logical.ReadOperation: b.handleMonitor, diff --git a/website/content/api-docs/system/monitor.mdx b/website/content/api-docs/system/monitor.mdx index d888b4417..e29f2cb46 100644 --- a/website/content/api-docs/system/monitor.mdx +++ b/website/content/api-docs/system/monitor.mdx @@ -26,6 +26,9 @@ default, this is text. - `log_level` `(string: "info")` – Specifies the log level to use when streaming logs. This defaults to `info` if not specified. +- `log_format` `(string: "standard")` – Specifies the log format to emit when streaming logs. Supported values are "standard" and "json". The default is `standard`. +if not specified. + ### Sample Request ```shell-session diff --git a/website/content/docs/commands/debug.mdx b/website/content/docs/commands/debug.mdx index f82460d24..4b8b938df 100644 --- a/website/content/docs/commands/debug.mdx +++ b/website/content/docs/commands/debug.mdx @@ -138,6 +138,10 @@ flags](/docs/commands) included on all commands. - `-interval` `(int or time string: "30s")` - The polling interval at which to collect profiling data and server state. The default is 30s. +- `-log-format` `(string: "standard")` - Log format to be captured if "log" + target specified. Supported values are "standard" and "json". The default is + "standard". + - `-metrics-interval` `(int or time string: "10s")` - The polling interval at which to collect metrics data. The default is 10s. diff --git a/website/content/docs/commands/monitor.mdx b/website/content/docs/commands/monitor.mdx index cbe40f0ee..e0afc5a91 100644 --- a/website/content/docs/commands/monitor.mdx +++ b/website/content/docs/commands/monitor.mdx @@ -41,3 +41,7 @@ flags](/docs/commands) included on all commands. - `-log-level` `(string: "info")` - Monitor the Vault server at this log level. Valid log levels are (in order of detail) "trace", "debug", "info", "warn", "error". If this option is not specified, "info" is used. + +- `-log-format` `(string: "standard")` - Format to emit logs. + Valid formats are "standard", and "json". + If this option is not specified, "standard" is used.