From 9501d44ed5b8b2e4a851f65a93f616528281c4a6 Mon Sep 17 00:00:00 2001 From: Chris Capurso <1036769+ccapurso@users.noreply.github.com> Date: Mon, 27 Jun 2022 11:39:53 -0400 Subject: [PATCH] Add endpoints to provide ability to modify logging verbosity (#16111) * add func to set level for specific logger * add endpoints to modify log level * initialize base logger with IndependentLevels * test to ensure other loggers remain unchanged * add DELETE loggers endpoints to revert back to config * add API docs page * add changelog entry * remove extraneous line * add log level field to Core struct * add godoc for getLogLevel * add some loggers to c.allLoggers --- changelog/16111.txt | 3 + command/server.go | 18 +- sdk/helper/logging/logging.go | 7 +- vault/cluster.go | 9 +- vault/core.go | 23 ++ vault/expiration.go | 8 +- vault/logical_system.go | 106 ++++++++ vault/logical_system_paths.go | 44 ++++ vault/logical_system_test.go | 271 ++++++++++++++++++++ vault/raft.go | 1 + vault/testing.go | 8 +- website/content/api-docs/system/loggers.mdx | 102 ++++++++ website/data/api-docs-nav-data.json | 4 + 13 files changed, 587 insertions(+), 17 deletions(-) create mode 100644 changelog/16111.txt create mode 100644 website/content/api-docs/system/loggers.mdx diff --git a/changelog/16111.txt b/changelog/16111.txt new file mode 100644 index 000000000..59d533076 --- /dev/null +++ b/changelog/16111.txt @@ -0,0 +1,3 @@ +```release-note:improvement +core: Add `sys/loggers` and `sys/loggers/:name` endpoints to provide ability to modify logging verbosity +``` diff --git a/command/server.go b/command/server.go index 4ba9a783e..52b84e616 100644 --- a/command/server.go +++ b/command/server.go @@ -460,8 +460,9 @@ func (c *ServerCommand) runRecoveryMode() int { } c.logger = hclog.NewInterceptLogger(&hclog.LoggerOptions{ - Output: c.gatedWriter, - Level: level, + Output: c.gatedWriter, + Level: level, + IndependentLevels: true, // Note that if logFormat is either unspecified or standard, then // the resulting logger's format will be standard. JSONFormat: logFormat == logging.JSONFormat, @@ -592,6 +593,7 @@ func (c *ServerCommand) runRecoveryMode() int { Physical: backend, StorageType: config.Storage.Type, Seal: barrierSeal, + LogLevel: logLevelString, Logger: c.logger, DisableMlock: config.DisableMlock, RecoveryMode: c.flagRecovery, @@ -1116,14 +1118,16 @@ func (c *ServerCommand) Run(args []string) int { if c.flagDevThreeNode || c.flagDevFourCluster { c.logger = hclog.NewInterceptLogger(&hclog.LoggerOptions{ - Mutex: &sync.Mutex{}, - Output: c.gatedWriter, - Level: hclog.Trace, + Mutex: &sync.Mutex{}, + Output: c.gatedWriter, + Level: hclog.Trace, + IndependentLevels: true, }) } else { c.logger = hclog.NewInterceptLogger(&hclog.LoggerOptions{ - Output: c.gatedWriter, - Level: level, + Output: c.gatedWriter, + Level: level, + IndependentLevels: true, // Note that if logFormat is either unspecified or standard, then // the resulting logger's format will be standard. JSONFormat: logFormat == logging.JSONFormat, diff --git a/sdk/helper/logging/logging.go b/sdk/helper/logging/logging.go index a8d30674b..211a545e3 100644 --- a/sdk/helper/logging/logging.go +++ b/sdk/helper/logging/logging.go @@ -42,9 +42,10 @@ func NewVaultLogger(level log.Level) log.Logger { // writer and a Vault formatter func NewVaultLoggerWithWriter(w io.Writer, level log.Level) log.Logger { opts := &log.LoggerOptions{ - Level: level, - Output: w, - JSONFormat: ParseEnvLogFormat() == JSONFormat, + Level: level, + IndependentLevels: true, + Output: w, + JSONFormat: ParseEnvLogFormat() == JSONFormat, } return log.New(opts) } diff --git a/vault/cluster.go b/vault/cluster.go index a1d037907..bc1d352e5 100644 --- a/vault/cluster.go +++ b/vault/cluster.go @@ -318,14 +318,19 @@ func (c *Core) startClusterListener(ctx context.Context) error { networkLayer := c.clusterNetworkLayer if networkLayer == nil { - networkLayer = cluster.NewTCPLayer(c.clusterListenerAddrs, c.logger.Named("cluster-listener.tcp")) + tcpLogger := c.logger.Named("cluster-listener.tcp") + networkLayer = cluster.NewTCPLayer(c.clusterListenerAddrs, tcpLogger) + c.AddLogger(tcpLogger) } + listenerLogger := c.logger.Named("cluster-listener") c.clusterListener.Store(cluster.NewListener(networkLayer, c.clusterCipherSuites, - c.logger.Named("cluster-listener"), + listenerLogger, 5*c.clusterHeartbeatInterval)) + c.AddLogger(listenerLogger) + err := c.getClusterListener().Run(ctx) if err != nil { return err diff --git a/vault/core.go b/vault/core.go index e00784f8a..8fbb5c5df 100644 --- a/vault/core.go +++ b/vault/core.go @@ -408,6 +408,9 @@ type Core struct { baseLogger log.Logger logger log.Logger + // log level provided by config, CLI flag, or env + logLevel string + // Disables the trace display for Sentinel checks sentinelTraceDisabled bool @@ -665,6 +668,8 @@ type CoreConfig struct { SecureRandomReader io.Reader + LogLevel string + Logger log.Logger // Disables the trace display for Sentinel checks @@ -848,6 +853,7 @@ func CreateCore(conf *CoreConfig) (*Core, error) { standbyStopCh: new(atomic.Value), baseLogger: conf.Logger, logger: conf.Logger.Named("core"), + logLevel: conf.LogLevel, defaultLeaseTTL: conf.DefaultLeaseTTL, maxLeaseTTL: conf.MaxLeaseTTL, @@ -1034,6 +1040,10 @@ func NewCore(conf *CoreConfig) (*Core, error) { c.loginMFABackend = NewLoginMFABackend(c, conf.Logger) + if c.loginMFABackend.mfaLogger != nil { + c.AddLogger(c.loginMFABackend.mfaLogger) + } + logicalBackends := make(map[string]logical.Factory) for k, f := range conf.LogicalBackends { logicalBackends[k] = f @@ -2816,6 +2826,19 @@ func (c *Core) SetLogLevel(level log.Level) { } } +func (c *Core) SetLogLevelByName(name string, level log.Level) error { + c.allLoggersLock.RLock() + defer c.allLoggersLock.RUnlock() + for _, logger := range c.allLoggers { + if logger.Name() == name { + logger.SetLevel(level) + return nil + } + } + + return fmt.Errorf("logger %q does not exist", name) +} + // SetConfig sets core's config object to the newly provided config. func (c *Core) SetConfig(conf *server.Config) { c.rawConfig.Store(conf) diff --git a/vault/expiration.go b/vault/expiration.go index 827864c38..4bda9bded 100644 --- a/vault/expiration.go +++ b/vault/expiration.go @@ -313,9 +313,12 @@ func getNumExpirationWorkers(c *Core, l log.Logger) int { // NewExpirationManager creates a new ExpirationManager that is backed // using a given view, and uses the provided router for revocation. func NewExpirationManager(c *Core, view *BarrierView, e ExpireLeaseStrategy, logger log.Logger) *ExpirationManager { - jobManager := fairshare.NewJobManager("expire", getNumExpirationWorkers(c, logger), logger.Named("job-manager"), c.metricSink) + managerLogger := logger.Named("job-manager") + jobManager := fairshare.NewJobManager("expire", getNumExpirationWorkers(c, logger), managerLogger, c.metricSink) jobManager.Start() + c.AddLogger(managerLogger) + exp := &ExpirationManager{ core: c, router: c.router, @@ -1268,7 +1271,8 @@ func (m *ExpirationManager) Renew(ctx context.Context, leaseID string, increment // RenewToken is used to renew a token which does not need to // invoke a logical backend. func (m *ExpirationManager) RenewToken(ctx context.Context, req *logical.Request, te *logical.TokenEntry, - increment time.Duration) (*logical.Response, error) { + increment time.Duration, +) (*logical.Response, error) { defer metrics.MeasureSince([]string{"expire", "renew-token"}, time.Now()) tokenNS, err := NamespaceByID(ctx, te.NamespaceID, m.core) diff --git a/vault/logical_system.go b/vault/logical_system.go index e4d168be2..5f85ec514 100644 --- a/vault/logical_system.go +++ b/vault/logical_system.go @@ -4436,6 +4436,112 @@ func (b *SystemBackend) handleVersionHistoryList(ctx context.Context, req *logic return logical.ListResponseWithInfo(respKeys, respKeyInfo), nil } +// getLogLevel returns the hclog.Level that corresponds with the provided level string. +// This differs hclog.LevelFromString in that it supports additional level strings so +// that in remains consistent with the handling found in the "vault server" command. +func getLogLevel(logLevel string) (log.Level, error) { + var level log.Level + + switch logLevel { + case "trace": + level = log.Trace + case "debug": + level = log.Debug + case "notice", "info", "": + level = log.Info + case "warn", "warning": + level = log.Warn + case "err", "error": + level = log.Error + default: + return level, fmt.Errorf("unrecognized log level %q", logLevel) + } + + return level, nil +} + +func (b *SystemBackend) handleLoggersWrite(ctx context.Context, req *logical.Request, d *framework.FieldData) (*logical.Response, error) { + logLevelRaw, ok := d.GetOk("level") + + if !ok { + return logical.ErrorResponse("level is required"), nil + } + + logLevel := logLevelRaw.(string) + if logLevel == "" { + return logical.ErrorResponse("level is empty"), nil + } + + level, err := getLogLevel(logLevel) + if err != nil { + return logical.ErrorResponse(fmt.Sprintf("invalid level provided: %s", err.Error())), nil + } + + b.Core.SetLogLevel(level) + + return nil, nil +} + +func (b *SystemBackend) handleLoggersDelete(ctx context.Context, req *logical.Request, d *framework.FieldData) (*logical.Response, error) { + level, err := getLogLevel(b.Core.logLevel) + if err != nil { + return logical.ErrorResponse(fmt.Sprintf("log level from config is invalid: %s", err.Error())), nil + } + + b.Core.SetLogLevel(level) + + return nil, nil +} + +func (b *SystemBackend) handleLoggersByNameWrite(ctx context.Context, req *logical.Request, d *framework.FieldData) (*logical.Response, error) { + nameRaw, nameOk := d.GetOk("name") + if !nameOk { + return logical.ErrorResponse("name is required"), nil + } + + logLevelRaw, logLevelOk := d.GetOk("level") + + if !logLevelOk { + return logical.ErrorResponse("level is required"), nil + } + + logLevel := logLevelRaw.(string) + if logLevel == "" { + return logical.ErrorResponse("level is empty"), nil + } + + level, err := getLogLevel(logLevel) + if err != nil { + return logical.ErrorResponse(fmt.Sprintf("invalid level provided: %s", err.Error())), nil + } + + err = b.Core.SetLogLevelByName(nameRaw.(string), level) + if err != nil { + return logical.ErrorResponse(fmt.Sprintf("invalid params: %s", err.Error())), nil + } + + return nil, nil +} + +func (b *SystemBackend) handleLoggersByNameDelete(ctx context.Context, req *logical.Request, d *framework.FieldData) (*logical.Response, error) { + nameRaw, ok := d.GetOk("name") + if !ok { + return logical.ErrorResponse("name is required"), nil + } + + level, err := getLogLevel(b.Core.logLevel) + if err != nil { + return logical.ErrorResponse(fmt.Sprintf("log level from config is invalid: %s", err.Error())), nil + } + + err = b.Core.SetLogLevelByName(nameRaw.(string), level) + if err != nil { + return logical.ErrorResponse(fmt.Sprintf("invalid params: %s", err.Error())), nil + } + + return nil, nil +} + func sanitizePath(path string) string { if !strings.HasSuffix(path, "/") { path += "/" diff --git a/vault/logical_system_paths.go b/vault/logical_system_paths.go index 82129c92b..6b1516217 100644 --- a/vault/logical_system_paths.go +++ b/vault/logical_system_paths.go @@ -288,6 +288,50 @@ func (b *SystemBackend) configPaths() []*framework.Path { }, }, }, + { + Pattern: "loggers$", + Fields: map[string]*framework.FieldSchema{ + "level": { + Type: framework.TypeString, + Description: "Log verbosity level. Supported values (in order of detail) are " + + "\"trace\", \"debug\", \"info\", \"warn\", and \"error\".", + }, + }, + Operations: map[logical.Operation]framework.OperationHandler{ + logical.UpdateOperation: &framework.PathOperation{ + Callback: b.handleLoggersWrite, + Summary: "Modify the log level for all existing loggers.", + }, + logical.DeleteOperation: &framework.PathOperation{ + Callback: b.handleLoggersDelete, + Summary: "Revert the all loggers to use log level provided in config.", + }, + }, + }, + { + Pattern: "loggers/" + framework.MatchAllRegex("name"), + Fields: map[string]*framework.FieldSchema{ + "name": { + Type: framework.TypeString, + Description: "The name of the logger to be modified.", + }, + "level": { + Type: framework.TypeString, + Description: "Log verbosity level. Supported values (in order of detail) are " + + "\"trace\", \"debug\", \"info\", \"warn\", and \"error\".", + }, + }, + Operations: map[logical.Operation]framework.OperationHandler{ + logical.UpdateOperation: &framework.PathOperation{ + Callback: b.handleLoggersByNameWrite, + Summary: "Modify the log level of a single logger.", + }, + logical.DeleteOperation: &framework.PathOperation{ + Callback: b.handleLoggersByNameDelete, + Summary: "Revert a single logger to use log level provided in config.", + }, + }, + }, } } diff --git a/vault/logical_system_test.go b/vault/logical_system_test.go index 4f889d713..b23df0d36 100644 --- a/vault/logical_system_test.go +++ b/vault/logical_system_test.go @@ -4556,3 +4556,274 @@ func TestProcessLimit(t *testing.T) { } } } + +func validateLevel(level string, logger hclog.Logger) bool { + switch level { + case "trace": + return logger.IsTrace() + case "debug": + return logger.IsDebug() + case "notice", "info", "": + return logger.IsInfo() + case "warn", "warning": + return logger.IsWarn() + case "err", "error": + return logger.IsError() + } + + return false +} + +func TestSystemBackend_Loggers(t *testing.T) { + testCases := []struct { + level string + expectError bool + }{ + { + "trace", + false, + }, + { + "debug", + false, + }, + { + "notice", + false, + }, + { + "info", + false, + }, + { + "warn", + false, + }, + { + "warning", + false, + }, + { + "err", + false, + }, + { + "error", + false, + }, + { + "", + true, + }, + { + "invalid", + true, + }, + } + + for _, tc := range testCases { + tc := tc + + t.Run(fmt.Sprintf("all-loggers-%s", tc.level), func(t *testing.T) { + t.Parallel() + + core, b, _ := testCoreSystemBackend(t) + config := core.GetCoreConfigInternal() + + req := &logical.Request{ + Path: "loggers", + Operation: logical.UpdateOperation, + Data: map[string]interface{}{ + "level": tc.level, + }, + } + + resp, err := b.HandleRequest(namespace.RootContext(nil), req) + respIsError := resp != nil && resp.IsError() + + if err != nil || (!tc.expectError && respIsError) { + t.Fatalf("unexpected error, err: %v, resp: %#v", err, resp) + } + + if tc.expectError && !respIsError { + t.Fatalf("expected response error, resp: %#v", resp) + } + + if !tc.expectError { + for _, logger := range core.allLoggers { + if !validateLevel(tc.level, logger) { + t.Fatalf("expected logger %q to be %q", logger.Name(), tc.level) + } + } + } + + req = &logical.Request{ + Path: fmt.Sprintf("loggers"), + Operation: logical.DeleteOperation, + } + + resp, err = b.HandleRequest(namespace.RootContext(nil), req) + if err != nil || (resp != nil && resp.IsError()) { + t.Fatalf("unexpected error, err: %v, resp: %#v", err, resp) + } + + for _, logger := range core.allLoggers { + if !validateLevel(config.LogLevel, logger) { + t.Errorf("expected level of logger %q to match original config", logger.Name()) + } + } + }) + } +} + +func TestSystemBackend_LoggersByName(t *testing.T) { + testCases := []struct { + logger string + level string + expectWriteError bool + expectDeleteError bool + }{ + { + "core", + "trace", + false, + false, + }, + { + "token", + "debug", + false, + false, + }, + { + "audit", + "notice", + false, + false, + }, + { + "expiration", + "info", + false, + false, + }, + { + "policy", + "warn", + false, + false, + }, + { + "activity", + "warning", + false, + false, + }, + { + "identity", + "err", + false, + false, + }, + { + "rollback", + "error", + false, + false, + }, + { + "system", + "", + true, + false, + }, + { + "quotas", + "invalid", + true, + false, + }, + { + "", + "info", + true, + true, + }, + { + "does_not_exist", + "error", + true, + true, + }, + } + + for _, tc := range testCases { + tc := tc + + t.Run(fmt.Sprintf("loggers-by-name-%s", tc.logger), func(t *testing.T) { + t.Parallel() + + core, b, _ := testCoreSystemBackend(t) + config := core.GetCoreConfigInternal() + + req := &logical.Request{ + Path: fmt.Sprintf("loggers/%s", tc.logger), + Operation: logical.UpdateOperation, + Data: map[string]interface{}{ + "name": tc.logger, + "level": tc.level, + }, + } + + resp, err := b.HandleRequest(namespace.RootContext(nil), req) + respIsError := resp != nil && resp.IsError() + + if err != nil || (!tc.expectWriteError && respIsError) { + t.Fatalf("unexpected error, err: %v, resp: %#v", err, resp) + } + + if tc.expectWriteError && !respIsError { + t.Fatalf("expected response error, resp: %#v", resp) + } + + if !tc.expectWriteError { + for _, logger := range core.allLoggers { + if logger.Name() != tc.logger && !validateLevel(config.LogLevel, logger) { + t.Errorf("expected level of logger %q to be unchanged", logger.Name()) + } + + if !validateLevel(tc.level, logger) { + t.Fatalf("expected logger %q to be %q", logger.Name(), tc.level) + } + } + } + + req = &logical.Request{ + Path: fmt.Sprintf("loggers/%s", tc.logger), + Operation: logical.DeleteOperation, + Data: map[string]interface{}{ + "name": tc.logger, + }, + } + + resp, err = b.HandleRequest(namespace.RootContext(nil), req) + respIsError = resp != nil && resp.IsError() + + if err != nil || (!tc.expectDeleteError && respIsError) { + t.Fatalf("unexpected error, err: %v, resp: %#v", err, resp) + } + + if tc.expectDeleteError && !respIsError { + t.Fatalf("expected response error, resp: %#v", resp) + } + + if !tc.expectDeleteError { + for _, logger := range core.allLoggers { + if !validateLevel(config.LogLevel, logger) { + t.Errorf("expected level of logger %q to match original config", logger.Name()) + } + } + } + }) + } +} diff --git a/vault/raft.go b/vault/raft.go index bf9f1c0af..89397e18d 100644 --- a/vault/raft.go +++ b/vault/raft.go @@ -220,6 +220,7 @@ func (c *Core) startPeriodicRaftTLSRotate(ctx context.Context) error { c.raftTLSRotationStopCh = make(chan struct{}) logger := c.logger.Named("raft") + c.AddLogger(logger) if c.isRaftHAOnly() { return c.raftTLSRotateDirect(ctx, logger, c.raftTLSRotationStopCh) diff --git a/vault/testing.go b/vault/testing.go index 652861c9b..97a9c76d4 100644 --- a/vault/testing.go +++ b/vault/testing.go @@ -1197,11 +1197,13 @@ func NewTestLogger(t testing.T) *TestLogger { // We send nothing on the regular logger, that way we can later deregister // the sink to stop logging during cluster cleanup. logger := log.NewInterceptLogger(&log.LoggerOptions{ - Output: ioutil.Discard, + Output: ioutil.Discard, + IndependentLevels: true, }) sink := log.NewSinkAdapter(&log.LoggerOptions{ - Output: output, - Level: log.Trace, + Output: output, + Level: log.Trace, + IndependentLevels: true, }) logger.RegisterSink(sink) return &TestLogger{ diff --git a/website/content/api-docs/system/loggers.mdx b/website/content/api-docs/system/loggers.mdx new file mode 100644 index 000000000..494395d04 --- /dev/null +++ b/website/content/api-docs/system/loggers.mdx @@ -0,0 +1,102 @@ +--- +layout: api +page_title: /sys/loggers - HTTP API +description: The `/sys/loggers` endpoint is used modify the verbosity level of logging. +--- + +# `/sys/loggers` + +The `/sys/loggers` endpoint is used modify the verbosity level of logging. + +## Modify verbosity level of all loggers + +| Method | Path | +| :------ | :------------- | +| `POST` | `/sys/loggers` | + +### Parameters + +- `level` `(string: )` – Specifies the log verbosity level to be set for all loggers. +Supported values (in order of detail) are `"trace"`, `"debug"`, `"info"`, `"warn"`, and `"error"`. + +### Sample Payload + +```json +{ + "level": "debug", +} +``` + +### Sample Request + +```shell-session +$ curl \ + --header "X-Vault-Token: ..." \ + --request POST \ + --data @payload.json \ + http://127.0.0.1:8200/v1/sys/loggers +``` + +## Modify verbosity level of a single logger + +| Method | Path | +| :------ | :------------------- | +| `POST` | `/sys/loggers/:name` | + +### Parameters + +- `name` `(string: )` – Specifies the logger to be modified (e.g. `audit`, `core`, `expiration`). +- `level` `(string: )` – Specifies the log verbosity level to be set for the provided logger. +Supported values (in order of detail) are `"trace"`, `"debug"`, `"info"`, `"warn"`, and `"error"`. + +### Sample Payload + +```json +{ + "level": "debug", +} +``` + +### Sample Request + +```shell-session +$ curl \ + --header "X-Vault-Token: ..." \ + --request POST \ + --data @payload.json \ + http://127.0.0.1:8200/v1/sys/loggers/core +``` + +## Revert verbosity of all loggers to configured level + +| Method | Path | +| :-------- | :------------- | +| `DELETE` | `/sys/loggers` | + +### Sample Request + +```shell-session +$ curl \ + --header "X-Vault-Token: ..." \ + --request DELETE \ + http://127.0.0.1:8200/v1/sys/loggers +``` + +## Revert verbosity of a single logger to configured level + +| Method | Path | +| :-------- | :------------------- | +| `DELETE` | `/sys/loggers/:name` | + +### Parameters + +- `name` `(string: )` – Specifies the logger to be modified (e.g. `audit`, `core`, `expiration`). + +### Sample Request + +```shell-session +$ curl \ + --header "X-Vault-Token: ..." \ + --request DELETE \ + http://127.0.0.1:8200/v1/sys/loggers/core +``` diff --git a/website/data/api-docs-nav-data.json b/website/data/api-docs-nav-data.json index 52b3db9bf..2c28ea388 100644 --- a/website/data/api-docs-nav-data.json +++ b/website/data/api-docs-nav-data.json @@ -482,6 +482,10 @@ "title": "/sys/license/status", "path": "system/license" }, + { + "title": "/sys/loggers", + "path": "system/loggers" + }, { "title": "/sys/managed-keys ENT", "path": "system/managed-keys"