From a30b7addd497bdbefdb21024c598daf12c73ad4e Mon Sep 17 00:00:00 2001 From: Chris Capurso <1036769+ccapurso@users.noreply.github.com> Date: Mon, 27 Jun 2022 15:39:53 +0000 Subject: [PATCH] backport of commit 3f9dbabfc162db8b575acb21f2b77141fd0c7e6c --- 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 000000000000..59d533076842 --- /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 8c640336dbc5..0f76b6ea9d18 100644 --- a/command/server.go +++ b/command/server.go @@ -458,8 +458,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, @@ -590,6 +591,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, @@ -1114,14 +1116,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 a8d30674b1b5..211a545e3360 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 a1d037907cd2..bc1d352e5337 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 0b996fe606c4..10a6309985ff 100644 --- a/vault/core.go +++ b/vault/core.go @@ -406,6 +406,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 @@ -656,6 +659,8 @@ type CoreConfig struct { SecureRandomReader io.Reader + LogLevel string + Logger log.Logger // Disables the trace display for Sentinel checks @@ -835,6 +840,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, @@ -1013,6 +1019,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 @@ -2788,6 +2798,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 6b8452328746..d2e0e3f62581 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, @@ -1264,7 +1267,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 869e8148a424..5e55247b19e7 100644 --- a/vault/logical_system.go +++ b/vault/logical_system.go @@ -4424,6 +4424,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 8e5513619788..b75d15dca817 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 3a258395b5bb..5e7f1534ba00 100644 --- a/vault/logical_system_test.go +++ b/vault/logical_system_test.go @@ -4553,3 +4553,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 daa919ea3414..c5b4300baf08 100644 --- a/vault/raft.go +++ b/vault/raft.go @@ -219,6 +219,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 f08753f2a65f..2185ee99013c 100644 --- a/vault/testing.go +++ b/vault/testing.go @@ -1191,11 +1191,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 000000000000..494395d0422a --- /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 c671b2d6ebdf..d9656d1db9b7 100644 --- a/website/data/api-docs-nav-data.json +++ b/website/data/api-docs-nav-data.json @@ -478,6 +478,10 @@ "title": "/sys/license", "path": "system/license" }, + { + "title": "/sys/loggers", + "path": "system/loggers" + }, { "title": "/sys/managed-keys ENT", "path": "system/managed-keys"