Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

api/monitor: Adding log format to monitor command and debug #15536

Merged
merged 4 commits into from
May 24, 2022
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
10 changes: 9 additions & 1 deletion api/sys_monitor.go
Original file line number Diff line number Diff line change
Expand Up @@ -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 == "" {
Expand All @@ -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() {
ncabatoff marked this conversation as resolved.
Show resolved Hide resolved
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
Expand Down
7 changes: 7 additions & 0 deletions changelog/15536.txt
Original file line number Diff line number Diff line change
@@ -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
```
15 changes: 13 additions & 2 deletions command/debug.go
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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
}

Expand Down Expand Up @@ -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
Expand Down
19 changes: 17 additions & 2 deletions command/monitor.go
Original file line number Diff line number Diff line change
Expand Up @@ -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{}
Expand Down Expand Up @@ -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
}
Expand Down Expand Up @@ -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())
Expand All @@ -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
Expand Down
41 changes: 41 additions & 0 deletions helper/monitor/monitor_test.go
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
package monitor

import (
"encoding/json"
"fmt"
"strings"
"testing"
Expand Down Expand Up @@ -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()

Expand Down
44 changes: 43 additions & 1 deletion http/sys_monitor_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,7 @@ package http

import (
"context"
"encoding/json"
"strings"
"testing"
"time"
Expand Down Expand Up @@ -35,13 +36,38 @@ 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,
Level: log.Debug,
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()
Expand All @@ -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++
}
Expand Down
25 changes: 19 additions & 6 deletions vault/logical_system.go
Original file line number Diff line number Diff line change
Expand Up @@ -741,7 +741,8 @@ func (b *SystemBackend) handleRekeyRetrieve(
ctx context.Context,
req *logical.Request,
data *framework.FieldData,
recovery bool) (*logical.Response, error) {
recovery bool,
) (*logical.Response, error) {
backup, err := b.Core.RekeyRetrieveBackup(ctx, recovery)
if err != nil {
return nil, fmt.Errorf("unable to look up backed-up keys: %w", err)
Expand Down Expand Up @@ -792,7 +793,8 @@ func (b *SystemBackend) handleRekeyDelete(
ctx context.Context,
req *logical.Request,
data *framework.FieldData,
recovery bool) (*logical.Response, error) {
recovery bool,
) (*logical.Response, error) {
err := b.Core.RekeyDeleteBackup(ctx, recovery)
if err != nil {
return nil, fmt.Errorf("error during deletion of backed-up keys: %w", err)
Expand Down Expand Up @@ -1082,7 +1084,8 @@ func (b *SystemBackend) handleReadMount(ctx context.Context, req *logical.Reques

// used to intercept an HTTPCodedError so it goes back to callee
func handleError(
err error) (*logical.Response, error) {
err error,
) (*logical.Response, error) {
if strings.Contains(err.Error(), logical.ErrReadOnly.Error()) {
return logical.ErrorResponse(err.Error()), err
}
Expand All @@ -1097,7 +1100,8 @@ func handleError(
// Performs a similar function to handleError, but upon seeing a ReadOnlyError
// will actually strip it out to prevent forwarding
func handleErrorNoReadOnlyForward(
err error) (*logical.Response, error) {
err error,
) (*logical.Response, error) {
if strings.Contains(err.Error(), logical.ErrReadOnly.Error()) {
return nil, fmt.Errorf("operation could not be completed as storage is read-only")
}
Expand Down Expand Up @@ -2007,7 +2011,8 @@ func (b *SystemBackend) handleRevokeForce(ctx context.Context, req *logical.Requ

// handleRevokePrefixCommon is used to revoke a prefix with many LeaseIDs
func (b *SystemBackend) handleRevokePrefixCommon(ctx context.Context,
req *logical.Request, data *framework.FieldData, force, sync bool) (*logical.Response, error) {
req *logical.Request, data *framework.FieldData, force, sync bool,
) (*logical.Response, error) {
// Get all the options
prefix := data.Get("prefix").(string)

Expand Down Expand Up @@ -3239,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
Expand All @@ -3253,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{
Expand Down
6 changes: 6 additions & 0 deletions vault/logical_system_paths.go
Original file line number Diff line number Diff line change
Expand Up @@ -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,
ncabatoff marked this conversation as resolved.
Show resolved Hide resolved
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,
Expand Down
3 changes: 3 additions & 0 deletions website/content/api-docs/system/monitor.mdx
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
4 changes: 4 additions & 0 deletions website/content/docs/commands/debug.mdx
Original file line number Diff line number Diff line change
Expand Up @@ -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.

Expand Down
4 changes: 4 additions & 0 deletions website/content/docs/commands/monitor.mdx
Original file line number Diff line number Diff line change
Expand Up @@ -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.