From 3463e906e468614328c305768606b60eeac030bb Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Tue, 2 Nov 2021 17:25:31 -0700 Subject: [PATCH 01/33] VAULT-1564 report in-flight requests --- command/debug.go | 69 +++++++++++++++++++- command/debug_test.go | 5 ++ http/handler.go | 24 +++++++ http/handler_test.go | 30 +++++++++ vault/core.go | 28 ++++++++ vault/core_metrics.go | 13 ++++ vault/logical_system.go | 40 ++++++++++++ vault/logical_system_paths.go | 13 ++++ website/content/docs/internals/telemetry.mdx | 1 + 9 files changed, 221 insertions(+), 2 deletions(-) diff --git a/command/debug.go b/command/debug.go index afd4471d0f74..994559b0084a 100644 --- a/command/debug.go +++ b/command/debug.go @@ -17,6 +17,7 @@ import ( "github.com/hashicorp/go-secure-stdlib/gatedwriter" "github.com/hashicorp/go-secure-stdlib/strutil" "github.com/hashicorp/vault/api" + "github.com/hashicorp/vault/sdk/helper/jsonutil" "github.com/hashicorp/vault/sdk/helper/logging" "github.com/hashicorp/vault/sdk/version" "github.com/mholt/archiver" @@ -106,6 +107,7 @@ type DebugCommand struct { metricsCollection []map[string]interface{} replicationStatusCollection []map[string]interface{} serverStatusCollection []map[string]interface{} + inflightStatusCollection []map[string]interface{} // cachedClient holds the client retrieved during preflight cachedClient *api.Client @@ -480,7 +482,7 @@ func (c *DebugCommand) preflight(rawArgs []string) (string, error) { } func (c *DebugCommand) defaultTargets() []string { - return []string{"config", "host", "metrics", "pprof", "replication-status", "server-status", "log"} + return []string{"config", "host", "in-flight-req", "metrics", "pprof", "replication-status", "server-status", "log"} } func (c *DebugCommand) captureStaticTargets() error { @@ -580,6 +582,16 @@ func (c *DebugCommand) capturePollingTargets() error { }) } + // Collect in-flight request status if target is specified + if strutil.StrListContains(c.flagTargets, "in-flight-req") { + g.Add(func() error { + c.collectInFlightRequestStatus(ctx) + return nil + }, func(error) { + cancelFunc() + }) + } + if strutil.StrListContains(c.flagTargets, "log") { g.Add(func() error { c.writeLogs(ctx) @@ -611,7 +623,9 @@ func (c *DebugCommand) capturePollingTargets() error { if err := c.persistCollection(c.hostInfoCollection, "host_info.json"); err != nil { c.UI.Error(fmt.Sprintf("Error writing data to %s: %v", "host_info.json", err)) } - + if err := c.persistCollection(c.inflightStatusCollection, "in_flight_info.json"); err != nil { + c.UI.Error(fmt.Sprintf("Error writing data to %s: %v", "in_flight_info.json", err)) + } return nil } @@ -880,6 +894,57 @@ func (c *DebugCommand) collectServerStatus(ctx context.Context) { } } +func (c *DebugCommand) collectInFlightRequestStatus(ctx context.Context) { + + idxCount := 0 + intervalTicker := time.Tick(c.flagInterval) + + for { + if idxCount > 0 { + select { + case <-ctx.Done(): + return + case <-intervalTicker: + } + } + + c.logger.Info("capturing inflight request status", "count", idxCount) + idxCount++ + + req := c.cachedClient.NewRequest("GET", "/v1/sys/in-flight-req") + resp, err := c.cachedClient.RawRequestWithContext(ctx, req) + if err != nil { + c.captureError("inFlightReq-status", err) + } + + var data map[string]interface{} + if resp != nil { + err = jsonutil.DecodeJSONFromReader(resp.Body, &data) + if err != nil { + c.captureError("inFlightReq-status", err) + } + resp.Body.Close() + + inFlightReqStatRaw, ok := data["data"] + if !ok { + c.captureError("inFlightReq-status", fmt.Errorf("failed to read in-flight-request data")) + } + inFlightReqStat, ok := inFlightReqStatRaw.(map[string]interface{}) + if !ok { + c.captureError("inFlightReq-status", fmt.Errorf("failed to parse in-flight-request data")) + } + + if inFlightReqStat != nil && len(inFlightReqStat) > 0 { + statusEntry := map[string]interface{}{ + "timestamp": time.Now().UTC(), + "in_flight_request": inFlightReqStat, + } + c.inflightStatusCollection = append(c.inflightStatusCollection, statusEntry) + } + } + } +} + // persistCollection writes the collected data for a particular target onto the // specified file. If the collection is empty, it returns immediately. func (c *DebugCommand) persistCollection(collection []map[string]interface{}, outFile string) error { diff --git a/command/debug_test.go b/command/debug_test.go index 885b0de63ef5..c24cbc3290bb 100644 --- a/command/debug_test.go +++ b/command/debug_test.go @@ -235,6 +235,11 @@ func TestDebugCommand_CaptureTargets(t *testing.T) { []string{"server-status"}, []string{"server_status.json"}, }, + { + "in-flight-req", + []string{"in-flight-req"}, + []string{"in_flight_info.json"}, + }, { "all-minus-pprof", []string{"config", "host", "metrics", "replication-status", "server-status"}, diff --git a/http/handler.go b/http/handler.go index 65b6094c31d4..690c913a61d9 100644 --- a/http/handler.go +++ b/http/handler.go @@ -6,6 +6,7 @@ import ( "encoding/json" "errors" "fmt" + "github.com/hashicorp/go-uuid" "io" "io/fs" "io/ioutil" @@ -146,6 +147,7 @@ func Handler(props *vault.HandlerProperties) http.Handler { mux.Handle("/v1/sys/leader", handleSysLeader(core)) mux.Handle("/v1/sys/health", handleSysHealth(core)) mux.Handle("/v1/sys/monitor", handleLogicalNoForward(core)) + mux.Handle("/v1/sys/in-flight-req", handleLogicalNoForward(core)) mux.Handle("/v1/sys/generate-root/attempt", handleRequestForwarding(core, handleAuditNonLogical(core, handleSysGenerateRootAttempt(core, vault.GenerateStandardRootTokenStrategy)))) mux.Handle("/v1/sys/generate-root/update", handleRequestForwarding(core, @@ -389,6 +391,25 @@ func wrapGenericHandler(core *vault.Core, h http.Handler, props *vault.HandlerPr hostname, _ := os.Hostname() return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + + // The uuid for the request is going to be generated when a logical + // request is generated. But, here we generate one to be able to track + // in-flight requests + inFlightReqID, err := uuid.GenerateUUID() + if err != nil { + respondError(w, http.StatusBadRequest, fmt.Errorf("failed to generate an identifier for the inflight request")) + } + err = core.StoreInFlightReqData( + inFlightReqID, + &vault.InFlightReqData { + StartTime: time.Now(), + ClientRemoteAddr: r.RemoteAddr, + ReqPath: r.URL.Path, + }) + if err != nil { + respondError(w, http.StatusBadRequest, err) + } + // This block needs to be here so that upon sending SIGHUP, custom response // headers are also reloaded into the handlers. if props.ListenerConfig != nil { @@ -464,6 +485,9 @@ func wrapGenericHandler(core *vault.Core, h http.Handler, props *vault.HandlerPr h.ServeHTTP(w, r) + // deleting the inflight request entry + core.DeleteInFlightReqData(inFlightReqID) + cancelFunc() return }) diff --git a/http/handler_test.go b/http/handler_test.go index b57b49527b21..85ddd4943aa9 100644 --- a/http/handler_test.go +++ b/http/handler_test.go @@ -294,6 +294,36 @@ func TestHandler_CacheControlNoStore(t *testing.T) { } } +func TestHandler_InFlightRequest(t *testing.T) { + core, _, token := vault.TestCoreUnsealed(t) + ln, addr := TestServer(t, core) + defer ln.Close() + TestServerAuth(t, addr, token) + + req, err := http.NewRequest("GET", addr+"/v1/sys/in-flight-req", nil) + if err != nil { + t.Fatalf("err: %s", err) + } + req.Header.Set(consts.AuthHeaderName, token) + + client := cleanhttp.DefaultClient() + resp, err := client.Do(req) + if err != nil { + t.Fatalf("err: %s", err) + } + + if resp == nil { + t.Fatalf("nil response") + } + + var actual map[string]interface{} + testResponseStatus(t, resp, 200) + testResponseBody(t, resp, &actual) + if actual == nil { + t.Fatalf("") + } +} + // TestHandler_MissingToken tests the response / error code if a request comes // in with a missing client token. See // https://github.com/hashicorp/vault/issues/8377 diff --git a/vault/core.go b/vault/core.go index 3b9242498d26..2997a06a2573 100644 --- a/vault/core.go +++ b/vault/core.go @@ -365,6 +365,9 @@ type Core struct { // metrics emission and sealing leading to a nil pointer metricsMutex sync.Mutex + // inFlightReqMap is used to store info about in-flight requests + inFlightReqMap *sync.Map + // metricSink is the destination for all metrics that have // a cluster label. metricSink *metricsutil.ClusterMetricSink @@ -846,6 +849,8 @@ func CreateCore(conf *CoreConfig) (*Core, error) { c.router.logger = c.logger.Named("router") c.allLoggers = append(c.allLoggers, c.router.logger) + c.inFlightReqMap = &sync.Map{} + c.SetConfig(conf.RawConfig) atomic.StoreUint32(c.replicationState, uint32(consts.ReplicationDRDisabled|consts.ReplicationPerformanceDisabled)) @@ -2939,3 +2944,26 @@ type LicenseState struct { ExpiryTime time.Time Terminated bool } + +type InFlightReqData struct { + StartTime time.Time `json:"start_time"` + ClientRemoteAddr string `json:"client_remote_address"` + ReqPath string `json:"request_path"` + Duration string `json:"duration"` +} + +func (c *Core) StoreInFlightReqData(reqID string, inFlightReqdata *InFlightReqData) error { + if c.inFlightReqMap == nil { + return fmt.Errorf("failed to store in-flight request data. Map not initialized") + } + c.inFlightReqMap.Store(reqID, inFlightReqdata) + return nil +} + +func (c *Core) DeleteInFlightReqData(reqID string) error{ + if c.inFlightReqMap == nil { + return fmt.Errorf("failed to delete in-flight request data. Map not initialized") + } + c.inFlightReqMap.Delete(reqID) + return nil +} diff --git a/vault/core_metrics.go b/vault/core_metrics.go index ececb0d92187..965e52f46481 100644 --- a/vault/core_metrics.go +++ b/vault/core_metrics.go @@ -91,6 +91,9 @@ func (c *Core) metricsLoop(stopCh chan struct{}) { c.metricSink.SetGaugeWithLabels([]string{"core", "replication", "dr", "secondary"}, 0, nil) } + // Capture the total number of in-flight requests + c.inFlightReqGaugeMetric() + // Refresh gauge metrics that are looped c.cachedGaugeMetricsEmitter() @@ -514,3 +517,13 @@ func (c *Core) cachedGaugeMetricsEmitter() { loopMetrics.Range(emit) } + +func (c *Core) inFlightReqGaugeMetric() { + totalInFlightReq := 0 + c.inFlightReqMap.Range(func(key, value interface{}) bool { + totalInFlightReq++ + return true + }) + // Adding a gauge metric to capture total number of inflight requests + c.metricSink.SetGaugeWithLabels([]string{"core", "in_flight_request"}, float32(totalInFlightReq), nil) +} diff --git a/vault/logical_system.go b/vault/logical_system.go index ba9027a7f921..669469ea1685 100644 --- a/vault/logical_system.go +++ b/vault/logical_system.go @@ -174,6 +174,7 @@ func NewSystemBackend(core *Core, logger log.Logger) *SystemBackend { b.Backend.Paths = append(b.Backend.Paths, b.remountPath()) b.Backend.Paths = append(b.Backend.Paths, b.metricsPath()) b.Backend.Paths = append(b.Backend.Paths, b.monitorPath()) + b.Backend.Paths = append(b.Backend.Paths, b.inFlightRequestPath()) b.Backend.Paths = append(b.Backend.Paths, b.hostInfoPath()) b.Backend.Paths = append(b.Backend.Paths, b.quotasPaths()...) b.Backend.Paths = append(b.Backend.Paths, b.rootActivityPaths()...) @@ -2955,6 +2956,37 @@ func (b *SystemBackend) handleMetrics(ctx context.Context, req *logical.Request, return b.Core.metricsHelper.ResponseForFormat(format), nil } +func (b *SystemBackend) handleInFlightRequestInfo(_ context.Context, req *logical.Request, data *framework.FieldData) (*logical.Response, error) { + now := time.Now() + currentInFlightReqMap := make(map[string]interface{}) + syncMapRangeResult := true + b.Core.inFlightReqMap.Range(func(key, value interface{}) bool { + v, ok := value.(*InFlightReqData) + if !ok { + syncMapRangeResult = false + return false + } + // don't report the request to the in-flight-req path + if v.ReqPath != "/v1/sys/in-flight-req" { + v.Duration = fmt.Sprintf("%v microseconds", now.Sub(v.StartTime).Microseconds()) + currentInFlightReqMap[key.(string)] = v + } + + return true + }) + + // TODO: should an error be returned here? and if so, what status code should be returned? 500 or 400? + if !syncMapRangeResult { + return nil, fmt.Errorf("failed to read recorded in-flight requests") + } + + resp := &logical.Response{} + resp.Data = currentInFlightReqMap + + return resp, nil + +} + func (b *SystemBackend) handleMonitor(ctx context.Context, req *logical.Request, data *framework.FieldData) (*logical.Response, error) { ll := data.Get("log_level").(string) w := req.ResponseWriter @@ -4793,6 +4825,14 @@ This path responds to the following HTTP methods. "Export the metrics aggregated for telemetry purpose.", "", }, + "in-flight-req": { + "reports in-flight requests", + ` +This path responds to the following HTTP methods. + GET / + Returns a map of in-flight requests. + `, + }, "internal-counters-requests": { "Currently unsupported. Previously, count of requests seen by this Vault cluster over time.", "Currently unsupported. Previously, count of requests seen by this Vault cluster over time. Not included in count: health checks, UI asset requests, requests forwarded from another cluster.", diff --git a/vault/logical_system_paths.go b/vault/logical_system_paths.go index 114406bc05f5..36621cdeee10 100644 --- a/vault/logical_system_paths.go +++ b/vault/logical_system_paths.go @@ -1343,6 +1343,19 @@ func (b *SystemBackend) monitorPath() *framework.Path { } } +func (b *SystemBackend) inFlightRequestPath() *framework.Path { + return &framework.Path{ + Pattern: "in-flight-req", + Operations: map[logical.Operation]framework.OperationHandler { + logical.ReadOperation: &framework.PathOperation{ + Callback: b.handleInFlightRequestInfo, + Summary: strings.TrimSpace(sysHelp["in-flight-req"][0]), + Description: strings.TrimSpace(sysHelp["in-flight-req"][1]), + }, + }, + } +} + func (b *SystemBackend) hostInfoPath() *framework.Path { return &framework.Path{ Pattern: "host-info/?", diff --git a/website/content/docs/internals/telemetry.mdx b/website/content/docs/internals/telemetry.mdx index 8ff1d4e252b2..86c598322062 100644 --- a/website/content/docs/internals/telemetry.mdx +++ b/website/content/docs/internals/telemetry.mdx @@ -91,6 +91,7 @@ These metrics represent operational aspects of the running Vault instance. | `vault.core.fetch_acl_and_token` | Duration of time taken by ACL and corresponding token entry fetches handled by Vault core | ms | summary | | `vault.core.handle_request` | Duration of time taken by requests handled by Vault core | ms | summary | | `vault.core.handle_login_request` | Duration of time taken by login requests handled by Vault core | ms | summary | +| `vault.core.in_flight_request` | Number of in-flight requests. | requests | gauge | | `vault.core.leadership_setup_failed` | Duration of time taken by cluster leadership setup failures which have occurred in a highly available Vault cluster. This should be monitored and alerted on for overall cluster leadership status. | ms | summary | | `vault.core.leadership_lost` | Duration of time taken by cluster leadership losses which have occurred in a highly available Vault cluster. This should be monitored and alerted on for overall cluster leadership status. | ms | summary | | `vault.core.license.expiration_time_epoch` | Time as epoch (seconds since Jan 1 1970) at which license will expire. | seconds | gauge | From 6420c0c21468b84998d2a891d9769776fff730ae Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Tue, 2 Nov 2021 17:38:16 -0700 Subject: [PATCH 02/33] adding a changelog --- changelog/13024.txt | 3 +++ 1 file changed, 3 insertions(+) create mode 100644 changelog/13024.txt diff --git a/changelog/13024.txt b/changelog/13024.txt new file mode 100644 index 000000000000..97aea1b90bd3 --- /dev/null +++ b/changelog/13024.txt @@ -0,0 +1,3 @@ +```release-note:feature +**Report in-flight requests**:Adding a trace capability to show in-flight requests, and a new gauge metric to show the total number of in-flight requests +``` From 2c3fefece73b7333bda99d8b20a8a8a2322784bd Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Tue, 2 Nov 2021 17:54:43 -0700 Subject: [PATCH 03/33] Changing some variable names and fixing comments --- command/debug.go | 18 +++++++++--------- command/debug_test.go | 2 +- http/handler.go | 4 ++-- 3 files changed, 12 insertions(+), 12 deletions(-) diff --git a/command/debug.go b/command/debug.go index 994559b0084a..57ec4dd43c9d 100644 --- a/command/debug.go +++ b/command/debug.go @@ -107,7 +107,7 @@ type DebugCommand struct { metricsCollection []map[string]interface{} replicationStatusCollection []map[string]interface{} serverStatusCollection []map[string]interface{} - inflightStatusCollection []map[string]interface{} + inFlightReqStatusCollection []map[string]interface{} // cachedClient holds the client retrieved during preflight cachedClient *api.Client @@ -623,8 +623,8 @@ func (c *DebugCommand) capturePollingTargets() error { if err := c.persistCollection(c.hostInfoCollection, "host_info.json"); err != nil { c.UI.Error(fmt.Sprintf("Error writing data to %s: %v", "host_info.json", err)) } - if err := c.persistCollection(c.inflightStatusCollection, "in_flight_info.json"); err != nil { - c.UI.Error(fmt.Sprintf("Error writing data to %s: %v", "in_flight_info.json", err)) + if err := c.persistCollection(c.inFlightReqStatusCollection, "in_flight_req_data.json"); err != nil { + c.UI.Error(fmt.Sprintf("Error writing data to %s: %v", "in_flight_req_data.json", err)) } return nil } @@ -908,7 +908,7 @@ func (c *DebugCommand) collectInFlightRequestStatus(ctx context.Context) { } } - c.logger.Info("capturing inflight request status", "count", idxCount) + c.logger.Info("capturing in-flight request status", "count", idxCount) idxCount++ req := c.cachedClient.NewRequest("GET", "/v1/sys/in-flight-req") @@ -925,21 +925,21 @@ func (c *DebugCommand) collectInFlightRequestStatus(ctx context.Context) { } resp.Body.Close() - inFlightReqStatRaw, ok := data["data"] + inFlightReqDataRaw, ok := data["data"] if !ok { c.captureError("inFlightReq-status", fmt.Errorf("failed to read in-flight-request data")) } - inFlightReqStat, ok := inFlightReqStatRaw.(map[string]interface{}) + inFlightReqData, ok := inFlightReqDataRaw.(map[string]interface{}) if !ok { c.captureError("inFlightReq-status", fmt.Errorf("failed to parse in-flight-request data")) } - if inFlightReqStat != nil && len(inFlightReqStat) > 0 { + if inFlightReqData != nil && len(inFlightReqData) > 0 { statusEntry := map[string]interface{}{ "timestamp": time.Now().UTC(), - "in_flight_request": inFlightReqStat, + "in_flight_requests": inFlightReqData, } - c.inflightStatusCollection = append(c.inflightStatusCollection, statusEntry) + c.inFlightReqStatusCollection = append(c.inFlightReqStatusCollection, statusEntry) } } } diff --git a/command/debug_test.go b/command/debug_test.go index c24cbc3290bb..91c2b8b876a9 100644 --- a/command/debug_test.go +++ b/command/debug_test.go @@ -238,7 +238,7 @@ func TestDebugCommand_CaptureTargets(t *testing.T) { { "in-flight-req", []string{"in-flight-req"}, - []string{"in_flight_info.json"}, + []string{"in_flight_req_data.json"}, }, { "all-minus-pprof", diff --git a/http/handler.go b/http/handler.go index 690c913a61d9..f162a59566bf 100644 --- a/http/handler.go +++ b/http/handler.go @@ -397,7 +397,7 @@ func wrapGenericHandler(core *vault.Core, h http.Handler, props *vault.HandlerPr // in-flight requests inFlightReqID, err := uuid.GenerateUUID() if err != nil { - respondError(w, http.StatusBadRequest, fmt.Errorf("failed to generate an identifier for the inflight request")) + respondError(w, http.StatusBadRequest, fmt.Errorf("failed to generate an identifier for the in-flight request")) } err = core.StoreInFlightReqData( inFlightReqID, @@ -485,7 +485,7 @@ func wrapGenericHandler(core *vault.Core, h http.Handler, props *vault.HandlerPr h.ServeHTTP(w, r) - // deleting the inflight request entry + // deleting the in-flight request entry core.DeleteInFlightReqData(inFlightReqID) cancelFunc() From e2031da6e58e61dd49ce7ee17f7472d8c828837a Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Tue, 2 Nov 2021 17:57:25 -0700 Subject: [PATCH 04/33] minor style change --- command/debug.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/command/debug.go b/command/debug.go index 57ec4dd43c9d..ad8019af7153 100644 --- a/command/debug.go +++ b/command/debug.go @@ -107,7 +107,7 @@ type DebugCommand struct { metricsCollection []map[string]interface{} replicationStatusCollection []map[string]interface{} serverStatusCollection []map[string]interface{} - inFlightReqStatusCollection []map[string]interface{} + inFlightReqStatusCollection []map[string]interface{} // cachedClient holds the client retrieved during preflight cachedClient *api.Client From 29c5f24bb2d2c3751931db1493a553d4105ec9f6 Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Wed, 3 Nov 2021 13:37:55 -0700 Subject: [PATCH 05/33] adding unauthenticated support for in-flight-req --- command/server/listener_test.go | 13 ++++ .../profiling_unauth_in_flight_access.hcl | 9 +++ http/handler.go | 6 +- http/handler_test.go | 76 +++++++++++++++++++ http/sys_in_flight_reqeusts_test.go | 46 +++++++++++ http/sys_in_flight_requests.go | 45 +++++++++++ internalshared/configutil/listener.go | 13 +++- vault/core.go | 8 ++ 8 files changed, 212 insertions(+), 4 deletions(-) create mode 100644 command/server/test-fixtures/profiling_unauth_in_flight_access.hcl create mode 100644 http/sys_in_flight_reqeusts_test.go create mode 100644 http/sys_in_flight_requests.go diff --git a/command/server/listener_test.go b/command/server/listener_test.go index 5b2271eefc34..c4d962d8bdf9 100644 --- a/command/server/listener_test.go +++ b/command/server/listener_test.go @@ -6,6 +6,7 @@ import ( "io" "net" "testing" + ) type testListenerConnFn func(net.Listener) (net.Conn, error) @@ -66,3 +67,15 @@ func testListenerImpl(t *testing.T, ln net.Listener, connFn testListenerConnFn, t.Fatalf("bad: %v", buf.String()) } } + + +func TestProfilingUnauthenticatedInFlightAccess(t *testing.T) { + + config, err := LoadConfigFile("./test-fixtures/profiling_unauth_in_flight_access.hcl") + if err != nil { + t.Fatalf("Error encountered when loading config %+v", err) + } + if !config.Listeners[0].Profiling.UnauthenticatedInFlightAccess { + t.Fatalf("failed to read UnauthenticatedInFlightAccess") + } +} \ No newline at end of file diff --git a/command/server/test-fixtures/profiling_unauth_in_flight_access.hcl b/command/server/test-fixtures/profiling_unauth_in_flight_access.hcl new file mode 100644 index 000000000000..d865fb8b05af --- /dev/null +++ b/command/server/test-fixtures/profiling_unauth_in_flight_access.hcl @@ -0,0 +1,9 @@ +storage "inmem" {} +listener "tcp" { + address = "127.0.0.1:8200" + tls_disable = true + profiling { + unauthenticated_in_flight_request_access = true + } +} +disable_mlock = true diff --git a/http/handler.go b/http/handler.go index f162a59566bf..6c2c15a93454 100644 --- a/http/handler.go +++ b/http/handler.go @@ -147,7 +147,6 @@ func Handler(props *vault.HandlerProperties) http.Handler { mux.Handle("/v1/sys/leader", handleSysLeader(core)) mux.Handle("/v1/sys/health", handleSysHealth(core)) mux.Handle("/v1/sys/monitor", handleLogicalNoForward(core)) - mux.Handle("/v1/sys/in-flight-req", handleLogicalNoForward(core)) mux.Handle("/v1/sys/generate-root/attempt", handleRequestForwarding(core, handleAuditNonLogical(core, handleSysGenerateRootAttempt(core, vault.GenerateStandardRootTokenStrategy)))) mux.Handle("/v1/sys/generate-root/update", handleRequestForwarding(core, @@ -198,6 +197,11 @@ func Handler(props *vault.HandlerProperties) http.Handler { mux.Handle("/v1/sys/pprof/", handleLogicalNoForward(core)) } + if props.ListenerConfig != nil && props.ListenerConfig.Profiling.UnauthenticatedInFlightAccess { + mux.Handle("/v1/sys/in-flight-req", handleUnAuthenticatedInFlightRequest(core)) + } else { + mux.Handle("/v1/sys/in-flight-req", handleLogicalNoForward(core)) + } additionalRoutes(mux, core) } diff --git a/http/handler_test.go b/http/handler_test.go index 85ddd4943aa9..b5675c5a2cd6 100644 --- a/http/handler_test.go +++ b/http/handler_test.go @@ -5,12 +5,14 @@ import ( "crypto/tls" "encoding/json" "errors" + "fmt" "io/ioutil" "net/http" "net/http/httptest" "net/textproto" "net/url" "reflect" + "strconv" "strings" "testing" "time" @@ -324,6 +326,80 @@ func TestHandler_InFlightRequest(t *testing.T) { } } +func TestHandler_InFlightRequestWithLoad(t *testing.T) { + core, _, token := vault.TestCoreUnsealed(t) + ln, addr := TestServer(t, core) + defer ln.Close() + TestServerAuth(t, addr, token) + + stop := make(chan string) + + go func() { + i := 0 + for { + select { + case <-stop: + return + default: + break + } + // WRITE + secResp := testHttpPut(t, token, addr+"/v1/secret/foo"+strconv.Itoa(i), map[string]interface{}{ + "data": "bar", + }) + testResponseStatus(t, secResp, 204) + i++ + } + }() + + timeout := time.After(10 * time.Second) + + for { + select { + case <-timeout: + stop <- "done" + return + default: + } + req, err := http.NewRequest("GET", addr+"/v1/sys/in-flight-req", nil) + if err != nil { + t.Fatalf("err: %s", err) + } + req.Header.Set(consts.AuthHeaderName, token) + + client := cleanhttp.DefaultClient() + resp, err := client.Do(req) + if err != nil { + t.Fatalf("err: %s", err) + } + + if resp == nil { + t.Fatalf("nil response") + } + + var actual map[string]interface{} + testResponseStatus(t, resp, 200) + testResponseBody(t, resp, &actual) + + if actual == nil { + t.Fatalf("") + } + inFlightReqDataRaw, ok := actual["data"] + if !ok { + t.Fatalf("failed to read in-flight-request data") + } + inFlightReqData, ok := inFlightReqDataRaw.(map[string]interface{}) + if !ok { + t.Fatalf("data assertion failed") + } + if inFlightReqData != nil || len(inFlightReqData) > 0 { + fmt.Println("found something", inFlightReqData) + stop <- "done" + return + } + } +} + // TestHandler_MissingToken tests the response / error code if a request comes // in with a missing client token. See // https://github.com/hashicorp/vault/issues/8377 diff --git a/http/sys_in_flight_reqeusts_test.go b/http/sys_in_flight_reqeusts_test.go new file mode 100644 index 000000000000..71550f13015d --- /dev/null +++ b/http/sys_in_flight_reqeusts_test.go @@ -0,0 +1,46 @@ +package http + +import ( + "testing" + + "github.com/hashicorp/vault/internalshared/configutil" + "github.com/hashicorp/vault/vault" +) + +func TestInFlightRequest(t *testing.T) { + conf := &vault.CoreConfig{} + core, _, token := vault.TestCoreUnsealedWithConfig(t, conf) + ln, addr := TestServer(t, core) + TestServerAuth(t, addr, token) + + // Default: Only authenticated access + resp := testHttpGet(t, "", addr+"/v1/sys/in-flight-req") + testResponseStatus(t, resp, 400) + resp = testHttpGet(t, token, addr+"/v1/sys/in-flight-req") + testResponseStatus(t, resp, 200) + + // Close listener + ln.Close() + + // Setup new custom listener with unauthenticated metrics access + ln, addr = TestListener(t) + props := &vault.HandlerProperties{ + Core: core, + ListenerConfig: &configutil.Listener{ + Profiling: configutil.ListenerProfiling{ + UnauthenticatedInFlightAccess: true, + }, + }, + } + TestServerWithListenerAndProperties(t, ln, addr, core, props) + defer ln.Close() + TestServerAuth(t, addr, token) + + // Test without token + resp = testHttpGet(t, "", addr+"/v1/sys/in-flight-req") + testResponseStatus(t, resp, 200) + + // Should also work with token + resp = testHttpGet(t, token, addr+"/v1/sys/in-flight-req") + testResponseStatus(t, resp, 200) +} diff --git a/http/sys_in_flight_requests.go b/http/sys_in_flight_requests.go new file mode 100644 index 000000000000..5adec1fe2541 --- /dev/null +++ b/http/sys_in_flight_requests.go @@ -0,0 +1,45 @@ +package http + +import ( + "fmt" + "net/http" + "time" + + "github.com/hashicorp/vault/vault" +) + +func handleUnAuthenticatedInFlightRequest(core *vault.Core) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + switch r.Method { + case "GET": + default: + respondError(w, http.StatusMethodNotAllowed, nil) + return + } + now := time.Now() + currentInFlightReqMap := make(map[string]interface{}) + syncMapRangeResult := true + core.RangeInFlightReqData(func(key, value interface{}) bool { + v, ok := value.(*vault.InFlightReqData) + if !ok { + syncMapRangeResult = false + return false + } + // don't report the request to the in-flight-req path + if v.ReqPath != "/v1/sys/in-flight-req" { + v.Duration = fmt.Sprintf("%v microseconds", now.Sub(v.StartTime).Microseconds()) + currentInFlightReqMap[key.(string)] = v + } + + return true + }) + + // TODO: should an error be returned here? and if so, what status code should be returned? 500 or 400? + if !syncMapRangeResult { + respondError(w, http.StatusInternalServerError, fmt.Errorf("failed to read recorded in-flight requests")) + return + } + + respondOk(w, currentInFlightReqMap) + }) +} diff --git a/internalshared/configutil/listener.go b/internalshared/configutil/listener.go index 64e618489fb9..5853a0e3de05 100644 --- a/internalshared/configutil/listener.go +++ b/internalshared/configutil/listener.go @@ -24,9 +24,11 @@ type ListenerTelemetry struct { } type ListenerProfiling struct { - UnusedKeys UnusedKeyMap `hcl:",unusedKeyPositions"` - UnauthenticatedPProfAccess bool `hcl:"-"` - UnauthenticatedPProfAccessRaw interface{} `hcl:"unauthenticated_pprof_access,alias:UnauthenticatedPProfAccessRaw"` + UnusedKeys UnusedKeyMap `hcl:",unusedKeyPositions"` + UnauthenticatedPProfAccess bool `hcl:"-"` + UnauthenticatedPProfAccessRaw interface{} `hcl:"unauthenticated_pprof_access,alias:UnauthenticatedPProfAccessRaw"` + UnauthenticatedInFlightAccess bool `hcl:"-"` + UnauthenticatedInFlightAccessRaw interface{} `hcl:"unauthenticated_in_flight_request_access,alias:unauthenticatedInFlightAccessRaw"` } // Listener is the listener configuration for the server. @@ -353,6 +355,11 @@ func ParseListeners(result *SharedConfig, list *ast.ObjectList) error { l.Profiling.UnauthenticatedPProfAccessRaw = nil } + if l.Profiling.UnauthenticatedInFlightAccessRaw != nil { + if l.Profiling.UnauthenticatedInFlightAccess, err = parseutil.ParseBool(l.Profiling.UnauthenticatedInFlightAccessRaw); err != nil { + return multierror.Prefix(fmt.Errorf("invalid value for profiling.unauthenticated_in_flight_request_access: %w", err), fmt.Sprintf("listeners.%d", i)) + } + } } // CORS diff --git a/vault/core.go b/vault/core.go index 2997a06a2573..bbbc3b3866f2 100644 --- a/vault/core.go +++ b/vault/core.go @@ -2967,3 +2967,11 @@ func (c *Core) DeleteInFlightReqData(reqID string) error{ c.inFlightReqMap.Delete(reqID) return nil } + +func (c *Core) RangeInFlightReqData(rangeFunc func(key, value interface{}) bool) error { + if c.inFlightReqMap == nil { + return fmt.Errorf("failed to range over in-flight request data. Map not initialized") + } + c.inFlightReqMap.Range(rangeFunc) + return nil +} \ No newline at end of file From 17a49289856468af3578f3c74da8673bcef4f78b Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Wed, 3 Nov 2021 15:01:08 -0700 Subject: [PATCH 06/33] adding documentation for the listener.profiling stanza --- http/handler_test.go | 3 +-- http/sys_in_flight_reqeusts_test.go | 2 +- vault/logical_system.go | 2 +- vault/logical_system_paths.go | 2 +- website/content/docs/configuration/listener/tcp.mdx | 3 +++ 5 files changed, 7 insertions(+), 5 deletions(-) diff --git a/http/handler_test.go b/http/handler_test.go index b5675c5a2cd6..7a468490921e 100644 --- a/http/handler_test.go +++ b/http/handler_test.go @@ -5,7 +5,6 @@ import ( "crypto/tls" "encoding/json" "errors" - "fmt" "io/ioutil" "net/http" "net/http/httptest" @@ -358,6 +357,7 @@ func TestHandler_InFlightRequestWithLoad(t *testing.T) { select { case <-timeout: stop <- "done" + t.Fatalf("could not capture any in-flight-req") return default: } @@ -393,7 +393,6 @@ func TestHandler_InFlightRequestWithLoad(t *testing.T) { t.Fatalf("data assertion failed") } if inFlightReqData != nil || len(inFlightReqData) > 0 { - fmt.Println("found something", inFlightReqData) stop <- "done" return } diff --git a/http/sys_in_flight_reqeusts_test.go b/http/sys_in_flight_reqeusts_test.go index 71550f13015d..98e72c4a443c 100644 --- a/http/sys_in_flight_reqeusts_test.go +++ b/http/sys_in_flight_reqeusts_test.go @@ -7,7 +7,7 @@ import ( "github.com/hashicorp/vault/vault" ) -func TestInFlightRequest(t *testing.T) { +func TestInFlightRequestUnauthenticated(t *testing.T) { conf := &vault.CoreConfig{} core, _, token := vault.TestCoreUnsealedWithConfig(t, conf) ln, addr := TestServer(t, core) diff --git a/vault/logical_system.go b/vault/logical_system.go index 669469ea1685..1eb171086aaf 100644 --- a/vault/logical_system.go +++ b/vault/logical_system.go @@ -2956,7 +2956,7 @@ func (b *SystemBackend) handleMetrics(ctx context.Context, req *logical.Request, return b.Core.metricsHelper.ResponseForFormat(format), nil } -func (b *SystemBackend) handleInFlightRequestInfo(_ context.Context, req *logical.Request, data *framework.FieldData) (*logical.Response, error) { +func (b *SystemBackend) handleInFlightRequestData(_ context.Context, req *logical.Request, data *framework.FieldData) (*logical.Response, error) { now := time.Now() currentInFlightReqMap := make(map[string]interface{}) syncMapRangeResult := true diff --git a/vault/logical_system_paths.go b/vault/logical_system_paths.go index 36621cdeee10..cf68a52f6d72 100644 --- a/vault/logical_system_paths.go +++ b/vault/logical_system_paths.go @@ -1348,7 +1348,7 @@ func (b *SystemBackend) inFlightRequestPath() *framework.Path { Pattern: "in-flight-req", Operations: map[logical.Operation]framework.OperationHandler { logical.ReadOperation: &framework.PathOperation{ - Callback: b.handleInFlightRequestInfo, + Callback: b.handleInFlightRequestData, Summary: strings.TrimSpace(sysHelp["in-flight-req"][0]), Description: strings.TrimSpace(sysHelp["in-flight-req"][1]), }, diff --git a/website/content/docs/configuration/listener/tcp.mdx b/website/content/docs/configuration/listener/tcp.mdx index 08cddd118dd4..572f01e1ba42 100644 --- a/website/content/docs/configuration/listener/tcp.mdx +++ b/website/content/docs/configuration/listener/tcp.mdx @@ -175,6 +175,8 @@ default value in the `"/sys/config/ui"` [API endpoint](/api/system/config-ui). - `unauthenticated_pprof_access` `(bool: false)` - If set to true, allows unauthenticated access to the `/v1/sys/pprof` endpoint. +- `unauthenticated_in_flight_request_access` `(bool: false)` - If set to true, allows + unauthenticated access to the `/v1/sys/in-flight-req` endpoint. ### `custom_response_headers` Parameters @@ -245,6 +247,7 @@ This example shows enabling unauthenticated profiling access. listener "tcp" { profiling { unauthenticated_pprof_access = true + unauthenticated_in_flight_request_access = true } } ``` From 18ab7da21ade2c728edd7847e1ede2f5ec5da16b Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Thu, 4 Nov 2021 17:20:49 -0700 Subject: [PATCH 07/33] adding an atomic counter for the inflight requests addressing comments --- command/debug.go | 32 +++++++++---------- command/debug_test.go | 4 +-- http/handler.go | 9 +++--- http/handler_test.go | 15 +++------ http/logical.go | 2 +- http/sys_in_flight_requests.go | 40 +++++++++++------------ vault/core.go | 58 ++++++++++++++++++++++------------ vault/core_metrics.go | 6 +--- vault/logical_system.go | 43 +++++++++++++------------ 9 files changed, 107 insertions(+), 102 deletions(-) diff --git a/command/debug.go b/command/debug.go index ad8019af7153..049f4cc26103 100644 --- a/command/debug.go +++ b/command/debug.go @@ -482,7 +482,7 @@ func (c *DebugCommand) preflight(rawArgs []string) (string, error) { } func (c *DebugCommand) defaultTargets() []string { - return []string{"config", "host", "in-flight-req", "metrics", "pprof", "replication-status", "server-status", "log"} + return []string{"config", "host", "requests", "metrics", "pprof", "replication-status", "server-status", "log"} } func (c *DebugCommand) captureStaticTargets() error { @@ -494,6 +494,7 @@ func (c *DebugCommand) captureStaticTargets() error { if err != nil { c.captureError("config", err) c.logger.Error("config: error capturing config state", "error", err) + return nil } if resp != nil && resp.Data != nil { @@ -583,7 +584,7 @@ func (c *DebugCommand) capturePollingTargets() error { } // Collect in-flight request status if target is specified - if strutil.StrListContains(c.flagTargets, "in-flight-req") { + if strutil.StrListContains(c.flagTargets, "requests") { g.Add(func() error { c.collectInFlightRequestStatus(ctx) return nil @@ -623,8 +624,8 @@ func (c *DebugCommand) capturePollingTargets() error { if err := c.persistCollection(c.hostInfoCollection, "host_info.json"); err != nil { c.UI.Error(fmt.Sprintf("Error writing data to %s: %v", "host_info.json", err)) } - if err := c.persistCollection(c.inFlightReqStatusCollection, "in_flight_req_data.json"); err != nil { - c.UI.Error(fmt.Sprintf("Error writing data to %s: %v", "in_flight_req_data.json", err)) + if err := c.persistCollection(c.inFlightReqStatusCollection, "requests.json"); err != nil { + c.UI.Error(fmt.Sprintf("Error writing data to %s: %v", "requests.json", err)) } return nil } @@ -649,6 +650,7 @@ func (c *DebugCommand) collectHostInfo(ctx context.Context) { resp, err := c.cachedClient.RawRequestWithContext(ctx, r) if err != nil { c.captureError("host", err) + return } if resp != nil { defer resp.Body.Close() @@ -656,6 +658,7 @@ func (c *DebugCommand) collectHostInfo(ctx context.Context) { secret, err := api.ParseSecret(resp.Body) if err != nil { c.captureError("host", err) + return } if secret != nil && secret.Data != nil { hostEntry := secret.Data @@ -843,6 +846,7 @@ func (c *DebugCommand) collectReplicationStatus(ctx context.Context) { resp, err := c.cachedClient.RawRequestWithContext(ctx, r) if err != nil { c.captureError("replication-status", err) + return } if resp != nil { defer resp.Body.Close() @@ -850,6 +854,7 @@ func (c *DebugCommand) collectReplicationStatus(ctx context.Context) { secret, err := api.ParseSecret(resp.Body) if err != nil { c.captureError("replication-status", err) + return } if secret != nil && secret.Data != nil { replicationEntry := secret.Data @@ -879,10 +884,12 @@ func (c *DebugCommand) collectServerStatus(ctx context.Context) { healthInfo, err := c.cachedClient.Sys().Health() if err != nil { c.captureError("server-status.health", err) + return } sealInfo, err := c.cachedClient.Sys().SealStatus() if err != nil { c.captureError("server-status.seal", err) + return } statusEntry := map[string]interface{}{ @@ -915,29 +922,22 @@ func (c *DebugCommand) collectInFlightRequestStatus(ctx context.Context) { resp, err := c.cachedClient.RawRequestWithContext(ctx, req) if err != nil { c.captureError("inFlightReq-status", err) + return } var data map[string]interface{} if resp != nil { + defer resp.Body.Close() err = jsonutil.DecodeJSONFromReader(resp.Body, &data) if err != nil { c.captureError("inFlightReq-status", err) - } - resp.Body.Close() - - inFlightReqDataRaw, ok := data["data"] - if !ok { - c.captureError("inFlightReq-status", fmt.Errorf("failed to read in-flight-request data")) - } - inFlightReqData, ok := inFlightReqDataRaw.(map[string]interface{}) - if !ok { - c.captureError("inFlightReq-status", fmt.Errorf("failed to parse in-flight-request data")) + return } - if inFlightReqData != nil && len(inFlightReqData) > 0 { + if data != nil && len(data) > 0 { statusEntry := map[string]interface{}{ "timestamp": time.Now().UTC(), - "in_flight_requests": inFlightReqData, + "in_flight_requests": data, } c.inFlightReqStatusCollection = append(c.inFlightReqStatusCollection, statusEntry) } diff --git a/command/debug_test.go b/command/debug_test.go index 91c2b8b876a9..7c46eb5bd671 100644 --- a/command/debug_test.go +++ b/command/debug_test.go @@ -237,8 +237,8 @@ func TestDebugCommand_CaptureTargets(t *testing.T) { }, { "in-flight-req", - []string{"in-flight-req"}, - []string{"in_flight_req_data.json"}, + []string{"requests"}, + []string{"requests.json"}, }, { "all-minus-pprof", diff --git a/http/handler.go b/http/handler.go index 6c2c15a93454..b6eed6c0f101 100644 --- a/http/handler.go +++ b/http/handler.go @@ -401,9 +401,9 @@ func wrapGenericHandler(core *vault.Core, h http.Handler, props *vault.HandlerPr // in-flight requests inFlightReqID, err := uuid.GenerateUUID() if err != nil { - respondError(w, http.StatusBadRequest, fmt.Errorf("failed to generate an identifier for the in-flight request")) + respondError(w, http.StatusInternalServerError, fmt.Errorf("failed to generate an identifier for the in-flight request")) } - err = core.StoreInFlightReqData( + core.StoreInFlightReqData( inFlightReqID, &vault.InFlightReqData { StartTime: time.Now(), @@ -413,6 +413,8 @@ func wrapGenericHandler(core *vault.Core, h http.Handler, props *vault.HandlerPr if err != nil { respondError(w, http.StatusBadRequest, err) } + // deleting the in-flight request entry + defer core.DeleteInFlightReqData(inFlightReqID) // This block needs to be here so that upon sending SIGHUP, custom response // headers are also reloaded into the handlers. @@ -489,9 +491,6 @@ func wrapGenericHandler(core *vault.Core, h http.Handler, props *vault.HandlerPr h.ServeHTTP(w, r) - // deleting the in-flight request entry - core.DeleteInFlightReqData(inFlightReqID) - cancelFunc() return }) diff --git a/http/handler_test.go b/http/handler_test.go index 7a468490921e..5ff763da770e 100644 --- a/http/handler_test.go +++ b/http/handler_test.go @@ -377,21 +377,14 @@ func TestHandler_InFlightRequestWithLoad(t *testing.T) { t.Fatalf("nil response") } - var actual map[string]interface{} + var inFlightReqData map[string]interface{} testResponseStatus(t, resp, 200) - testResponseBody(t, resp, &actual) + testResponseBody(t, resp, &inFlightReqData) - if actual == nil { + if inFlightReqData == nil { t.Fatalf("") } - inFlightReqDataRaw, ok := actual["data"] - if !ok { - t.Fatalf("failed to read in-flight-request data") - } - inFlightReqData, ok := inFlightReqDataRaw.(map[string]interface{}) - if !ok { - t.Fatalf("data assertion failed") - } + if inFlightReqData != nil || len(inFlightReqData) > 0 { stop <- "done" return diff --git a/http/logical.go b/http/logical.go index a7730033b351..4a978b2d4997 100644 --- a/http/logical.go +++ b/http/logical.go @@ -183,7 +183,7 @@ func buildLogicalRequestNoAuth(perfStandby bool, w http.ResponseWriter, r *http. requestId, err := uuid.GenerateUUID() if err != nil { - return nil, nil, http.StatusBadRequest, fmt.Errorf("failed to generate identifier for the request: %w", err) + return nil, nil, http.StatusInternalServerError, fmt.Errorf("failed to generate identifier for the request: %w", err) } req := &logical.Request{ diff --git a/http/sys_in_flight_requests.go b/http/sys_in_flight_requests.go index 5adec1fe2541..ed13dac55d84 100644 --- a/http/sys_in_flight_requests.go +++ b/http/sys_in_flight_requests.go @@ -1,6 +1,7 @@ package http import ( + "encoding/json" "fmt" "net/http" "time" @@ -17,29 +18,26 @@ func handleUnAuthenticatedInFlightRequest(core *vault.Core) http.Handler { return } now := time.Now() - currentInFlightReqMap := make(map[string]interface{}) - syncMapRangeResult := true - core.RangeInFlightReqData(func(key, value interface{}) bool { - v, ok := value.(*vault.InFlightReqData) - if !ok { - syncMapRangeResult = false - return false - } - // don't report the request to the in-flight-req path - if v.ReqPath != "/v1/sys/in-flight-req" { - v.Duration = fmt.Sprintf("%v microseconds", now.Sub(v.StartTime).Microseconds()) - currentInFlightReqMap[key.(string)] = v - } - - return true - }) - - // TODO: should an error be returned here? and if so, what status code should be returned? 500 or 400? - if !syncMapRangeResult { - respondError(w, http.StatusInternalServerError, fmt.Errorf("failed to read recorded in-flight requests")) + + currentInFlightReqMap, err := core.GetInFlightReqData() + if err != nil { + respondError(w, http.StatusInternalServerError, err) return } - respondOk(w, currentInFlightReqMap) + for _, v := range currentInFlightReqMap { + v.SnapshotTime = now + } + + content, err := json.Marshal(currentInFlightReqMap) + if err != nil { + respondError(w, http.StatusInternalServerError, fmt.Errorf("error while marshalling the in-flight requests data: %w", err)) + return + } + + w.Header().Set("Content-Type", "application/json") + w.WriteHeader(http.StatusOK) + w.Write(content) + }) } diff --git a/vault/core.go b/vault/core.go index bbbc3b3866f2..a0833ab652e4 100644 --- a/vault/core.go +++ b/vault/core.go @@ -366,7 +366,7 @@ type Core struct { metricsMutex sync.Mutex // inFlightReqMap is used to store info about in-flight requests - inFlightReqMap *sync.Map + inFlightReqData *InFlightRequests // metricSink is the destination for all metrics that have // a cluster label. @@ -849,7 +849,10 @@ func CreateCore(conf *CoreConfig) (*Core, error) { c.router.logger = c.logger.Named("router") c.allLoggers = append(c.allLoggers, c.router.logger) - c.inFlightReqMap = &sync.Map{} + c.inFlightReqData = &InFlightRequests{ + InFlightReqMap: &sync.Map{}, + InFlightReqCount: uberAtomic.NewUint64(0), + } c.SetConfig(conf.RawConfig) @@ -2945,33 +2948,48 @@ type LicenseState struct { Terminated bool } +type InFlightRequests struct { + InFlightReqMap *sync.Map + InFlightReqCount *uberAtomic.Uint64 +} + type InFlightReqData struct { StartTime time.Time `json:"start_time"` ClientRemoteAddr string `json:"client_remote_address"` ReqPath string `json:"request_path"` - Duration string `json:"duration"` + SnapshotTime time.Time `json:"snapshot_time"` } -func (c *Core) StoreInFlightReqData(reqID string, inFlightReqdata *InFlightReqData) error { - if c.inFlightReqMap == nil { - return fmt.Errorf("failed to store in-flight request data. Map not initialized") - } - c.inFlightReqMap.Store(reqID, inFlightReqdata) - return nil +func (c *Core) StoreInFlightReqData(reqID string, data *InFlightReqData) { + c.inFlightReqData.InFlightReqMap.Store(reqID, data) + c.inFlightReqData.InFlightReqCount.Inc() + } -func (c *Core) DeleteInFlightReqData(reqID string) error{ - if c.inFlightReqMap == nil { - return fmt.Errorf("failed to delete in-flight request data. Map not initialized") - } - c.inFlightReqMap.Delete(reqID) - return nil +func (c *Core) DeleteInFlightReqData(reqID string) { + c.inFlightReqData.InFlightReqMap.Delete(reqID) + c.inFlightReqData.InFlightReqCount.Dec() } -func (c *Core) RangeInFlightReqData(rangeFunc func(key, value interface{}) bool) error { - if c.inFlightReqMap == nil { - return fmt.Errorf("failed to range over in-flight request data. Map not initialized") +func (c *Core) GetInFlightReqData() (map[string]*InFlightReqData, error) { + + currentInFlightReqMap := make(map[string]*InFlightReqData) + syncMapRangeResult := true + c.inFlightReqData.InFlightReqMap.Range(func(key, value interface{}) bool { + v, ok := value.(*InFlightReqData) + if !ok { + syncMapRangeResult = false + return false + } + + currentInFlightReqMap[key.(string)] = v + + return true + }) + + if !syncMapRangeResult { + return nil, fmt.Errorf("failed to read the recorded in-flight requests") } - c.inFlightReqMap.Range(rangeFunc) - return nil + + return currentInFlightReqMap, nil } \ No newline at end of file diff --git a/vault/core_metrics.go b/vault/core_metrics.go index 965e52f46481..92c46960e5a1 100644 --- a/vault/core_metrics.go +++ b/vault/core_metrics.go @@ -519,11 +519,7 @@ func (c *Core) cachedGaugeMetricsEmitter() { } func (c *Core) inFlightReqGaugeMetric() { - totalInFlightReq := 0 - c.inFlightReqMap.Range(func(key, value interface{}) bool { - totalInFlightReq++ - return true - }) + totalInFlightReq := c.inFlightReqData.InFlightReqCount.Load() // Adding a gauge metric to capture total number of inflight requests c.metricSink.SetGaugeWithLabels([]string{"core", "in_flight_request"}, float32(totalInFlightReq), nil) } diff --git a/vault/logical_system.go b/vault/logical_system.go index 1eb171086aaf..1ef06e466b8a 100644 --- a/vault/logical_system.go +++ b/vault/logical_system.go @@ -2957,31 +2957,32 @@ func (b *SystemBackend) handleMetrics(ctx context.Context, req *logical.Request, } func (b *SystemBackend) handleInFlightRequestData(_ context.Context, req *logical.Request, data *framework.FieldData) (*logical.Response, error) { - now := time.Now() - currentInFlightReqMap := make(map[string]interface{}) - syncMapRangeResult := true - b.Core.inFlightReqMap.Range(func(key, value interface{}) bool { - v, ok := value.(*InFlightReqData) - if !ok { - syncMapRangeResult = false - return false - } - // don't report the request to the in-flight-req path - if v.ReqPath != "/v1/sys/in-flight-req" { - v.Duration = fmt.Sprintf("%v microseconds", now.Sub(v.StartTime).Microseconds()) - currentInFlightReqMap[key.(string)] = v - } + resp := &logical.Response{ + Data: map[string]interface{}{ + logical.HTTPContentType: "text/plain", + logical.HTTPStatusCode: http.StatusInternalServerError, + }, + } - return true - }) + now := time.Now() + currentInFlightReqMap, err := b.Core.GetInFlightReqData() + if err != nil { + resp.Data[logical.HTTPRawBody] = err.Error() + return resp, nil + } - // TODO: should an error be returned here? and if so, what status code should be returned? 500 or 400? - if !syncMapRangeResult { - return nil, fmt.Errorf("failed to read recorded in-flight requests") + for _, v := range currentInFlightReqMap { + v.SnapshotTime = now } - resp := &logical.Response{} - resp.Data = currentInFlightReqMap + content, err := json.Marshal(currentInFlightReqMap) + if err != nil { + resp.Data[logical.HTTPRawBody] = fmt.Sprintf("error while marshalling the in-flight requests data: %s", err) + return resp, nil + } + resp.Data[logical.HTTPContentType] = "application/json" + resp.Data[logical.HTTPRawBody] = content + resp.Data[logical.HTTPStatusCode] = http.StatusOK return resp, nil From 660ff968b9ca4434643c3111dce27cc6fc96b489 Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Fri, 5 Nov 2021 07:42:32 -0700 Subject: [PATCH 08/33] addressing comments --- command/debug.go | 16 ++++++---------- http/handler.go | 3 --- http/sys_in_flight_requests.go | 6 +----- vault/core.go | 17 ++++------------- vault/logical_system.go | 6 +----- 5 files changed, 12 insertions(+), 36 deletions(-) diff --git a/command/debug.go b/command/debug.go index 049f4cc26103..4e6a12a6c3e5 100644 --- a/command/debug.go +++ b/command/debug.go @@ -884,12 +884,10 @@ func (c *DebugCommand) collectServerStatus(ctx context.Context) { healthInfo, err := c.cachedClient.Sys().Health() if err != nil { c.captureError("server-status.health", err) - return } sealInfo, err := c.cachedClient.Sys().SealStatus() if err != nil { c.captureError("server-status.seal", err) - return } statusEntry := map[string]interface{}{ @@ -921,7 +919,7 @@ func (c *DebugCommand) collectInFlightRequestStatus(ctx context.Context) { req := c.cachedClient.NewRequest("GET", "/v1/sys/in-flight-req") resp, err := c.cachedClient.RawRequestWithContext(ctx, req) if err != nil { - c.captureError("inFlightReq-status", err) + c.captureError("requests", err) return } @@ -930,17 +928,15 @@ func (c *DebugCommand) collectInFlightRequestStatus(ctx context.Context) { defer resp.Body.Close() err = jsonutil.DecodeJSONFromReader(resp.Body, &data) if err != nil { - c.captureError("inFlightReq-status", err) + c.captureError("requests", err) return } - if data != nil && len(data) > 0 { - statusEntry := map[string]interface{}{ - "timestamp": time.Now().UTC(), - "in_flight_requests": data, - } - c.inFlightReqStatusCollection = append(c.inFlightReqStatusCollection, statusEntry) + statusEntry := map[string]interface{}{ + "timestamp": time.Now().UTC(), + "in_flight_requests": data, } + c.inFlightReqStatusCollection = append(c.inFlightReqStatusCollection, statusEntry) } } } diff --git a/http/handler.go b/http/handler.go index b6eed6c0f101..e3d3333382e7 100644 --- a/http/handler.go +++ b/http/handler.go @@ -410,9 +410,6 @@ func wrapGenericHandler(core *vault.Core, h http.Handler, props *vault.HandlerPr ClientRemoteAddr: r.RemoteAddr, ReqPath: r.URL.Path, }) - if err != nil { - respondError(w, http.StatusBadRequest, err) - } // deleting the in-flight request entry defer core.DeleteInFlightReqData(inFlightReqID) diff --git a/http/sys_in_flight_requests.go b/http/sys_in_flight_requests.go index ed13dac55d84..f28da766d2fb 100644 --- a/http/sys_in_flight_requests.go +++ b/http/sys_in_flight_requests.go @@ -19,11 +19,7 @@ func handleUnAuthenticatedInFlightRequest(core *vault.Core) http.Handler { } now := time.Now() - currentInFlightReqMap, err := core.GetInFlightReqData() - if err != nil { - respondError(w, http.StatusInternalServerError, err) - return - } + currentInFlightReqMap := core.GetInFlightReqData() for _, v := range currentInFlightReqMap { v.SnapshotTime = now diff --git a/vault/core.go b/vault/core.go index a0833ab652e4..1f12f7071cd8 100644 --- a/vault/core.go +++ b/vault/core.go @@ -2971,25 +2971,16 @@ func (c *Core) DeleteInFlightReqData(reqID string) { c.inFlightReqData.InFlightReqCount.Dec() } -func (c *Core) GetInFlightReqData() (map[string]*InFlightReqData, error) { +func (c *Core) GetInFlightReqData() map[string]*InFlightReqData { currentInFlightReqMap := make(map[string]*InFlightReqData) - syncMapRangeResult := true c.inFlightReqData.InFlightReqMap.Range(func(key, value interface{}) bool { - v, ok := value.(*InFlightReqData) - if !ok { - syncMapRangeResult = false - return false - } - + // there is only one writer to this map, so skip checking for errors + v, _ := value.(*InFlightReqData) currentInFlightReqMap[key.(string)] = v return true }) - if !syncMapRangeResult { - return nil, fmt.Errorf("failed to read the recorded in-flight requests") - } - - return currentInFlightReqMap, nil + return currentInFlightReqMap } \ No newline at end of file diff --git a/vault/logical_system.go b/vault/logical_system.go index 1ef06e466b8a..0f19d748be4a 100644 --- a/vault/logical_system.go +++ b/vault/logical_system.go @@ -2965,11 +2965,7 @@ func (b *SystemBackend) handleInFlightRequestData(_ context.Context, req *logica } now := time.Now() - currentInFlightReqMap, err := b.Core.GetInFlightReqData() - if err != nil { - resp.Data[logical.HTTPRawBody] = err.Error() - return resp, nil - } + currentInFlightReqMap := b.Core.GetInFlightReqData() for _, v := range currentInFlightReqMap { v.SnapshotTime = now From b2979d5620c03528193844f836d5ffa0bad53ff5 Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Wed, 17 Nov 2021 15:01:35 -0800 Subject: [PATCH 09/33] logging completed requests --- command/server.go | 3 + command/server/config.go | 16 +++++ command/server/config_test_helpers.go | 1 + command/server/test-fixtures/config3.hcl | 1 + http/handler.go | 90 ++++++++++++++++++------ http/sys_in_flight_requests.go | 2 +- sdk/logical/response.go | 22 +++++- vault/core.go | 57 +++++++++++++-- vault/logical_system.go | 2 +- vault/request_handling.go | 18 ++++- vault/testing.go | 1 + 11 files changed, 179 insertions(+), 34 deletions(-) diff --git a/command/server.go b/command/server.go index 718009b8cf41..53cb97779713 100644 --- a/command/server.go +++ b/command/server.go @@ -1547,6 +1547,9 @@ func (c *ServerCommand) Run(args []string) int { c.logger.Error(err.Error()) } + // Setting log request with the new value in the config after reload + core.SetLogRequests() + if config.LogLevel != "" { configLogLevel := strings.ToLower(strings.TrimSpace(config.LogLevel)) switch configLogLevel { diff --git a/command/server/config.go b/command/server/config.go index c478906a7928..b55e5eddaa46 100644 --- a/command/server/config.go +++ b/command/server/config.go @@ -77,6 +77,9 @@ type Config struct { EnableResponseHeaderHostname bool `hcl:"-"` EnableResponseHeaderHostnameRaw interface{} `hcl:"enable_response_header_hostname"` + EnableLogRequests bool `hcl:"-"` + EnableLogRequestsRaw interface{} `hcl:"enable_log_requests"` + EnableResponseHeaderRaftNodeID bool `hcl:"-"` EnableResponseHeaderRaftNodeIDRaw interface{} `hcl:"enable_response_header_raft_node_id"` @@ -292,6 +295,11 @@ func (c *Config) Merge(c2 *Config) *Config { result.EnableResponseHeaderHostname = c2.EnableResponseHeaderHostname } + result.EnableLogRequests = c.EnableLogRequests + if c2.EnableLogRequests { + result.EnableLogRequests = c2.EnableLogRequests + } + result.EnableResponseHeaderRaftNodeID = c.EnableResponseHeaderRaftNodeID if c2.EnableResponseHeaderRaftNodeID { result.EnableResponseHeaderRaftNodeID = c2.EnableResponseHeaderRaftNodeID @@ -480,6 +488,12 @@ func ParseConfig(d, source string) (*Config, error) { } } + if result.EnableLogRequestsRaw != nil { + if result.EnableLogRequests, err = parseutil.ParseBool(result.EnableLogRequestsRaw); err != nil { + return nil, err + } + } + if result.EnableResponseHeaderRaftNodeIDRaw != nil { if result.EnableResponseHeaderRaftNodeID, err = parseutil.ParseBool(result.EnableResponseHeaderRaftNodeIDRaw); err != nil { return nil, err @@ -840,6 +854,8 @@ func (c *Config) Sanitized() map[string]interface{} { "enable_response_header_hostname": c.EnableResponseHeaderHostname, "enable_response_header_raft_node_id": c.EnableResponseHeaderRaftNodeID, + + "enable_log_requests": c.EnableLogRequests, } for k, v := range sharedResult { result[k] = v diff --git a/command/server/config_test_helpers.go b/command/server/config_test_helpers.go index 106ad7dce22b..df3171074a0e 100644 --- a/command/server/config_test_helpers.go +++ b/command/server/config_test_helpers.go @@ -701,6 +701,7 @@ func testConfig_Sanitized(t *testing.T) { "enable_ui": true, "enable_response_header_hostname": false, "enable_response_header_raft_node_id": false, + "enable_log_requests": true, "ha_storage": map[string]interface{}{ "cluster_addr": "top_level_cluster_addr", "disable_clustering": true, diff --git a/command/server/test-fixtures/config3.hcl b/command/server/test-fixtures/config3.hcl index 3394d04f57f5..659d0897fb0f 100644 --- a/command/server/test-fixtures/config3.hcl +++ b/command/server/test-fixtures/config3.hcl @@ -1,5 +1,6 @@ disable_cache = true disable_mlock = true +enable_log_requests = true ui = true diff --git a/http/handler.go b/http/handler.go index e3d3333382e7..553fc8301f27 100644 --- a/http/handler.go +++ b/http/handler.go @@ -20,6 +20,7 @@ import ( "regexp" "strconv" "strings" + "sync/atomic" "time" "github.com/NYTimes/gziphandler" @@ -224,6 +225,8 @@ func Handler(props *vault.HandlerProperties) http.Handler { type WrappingResponseWriter interface { http.ResponseWriter Wrapped() http.ResponseWriter + StatusCode() int + SetHeaders(h map[string][]*vault.CustomHeader) } type statusHeaderResponseWriter struct { @@ -231,9 +234,24 @@ type statusHeaderResponseWriter struct { logger log.Logger wroteHeader bool statusCode int + written *uint32 headers map[string][]*vault.CustomHeader } + +// Written tells us if the writer has been written to yet. +func (w *statusHeaderResponseWriter) Written() bool { + return atomic.LoadUint32(w.written) == 1 +} + +func (w *statusHeaderResponseWriter) StatusCode() int { + return w.statusCode +} + +func (w *statusHeaderResponseWriter) SetHeaders(h map[string][]*vault.CustomHeader) { + w.headers = h +} + func (w *statusHeaderResponseWriter) Wrapped() http.ResponseWriter { return w.wrapped } @@ -270,7 +288,6 @@ func (w *statusHeaderResponseWriter) WriteHeader(statusCode int) { func (w *statusHeaderResponseWriter) setCustomResponseHeaders(status int) { sch := w.headers if sch == nil { - w.logger.Warn("status code header map not configured") return } @@ -396,22 +413,13 @@ func wrapGenericHandler(core *vault.Core, h http.Handler, props *vault.HandlerPr return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - // The uuid for the request is going to be generated when a logical - // request is generated. But, here we generate one to be able to track - // in-flight requests - inFlightReqID, err := uuid.GenerateUUID() - if err != nil { - respondError(w, http.StatusInternalServerError, fmt.Errorf("failed to generate an identifier for the in-flight request")) + w = &statusHeaderResponseWriter{ + wrapped: w, + logger: core.Logger(), + wroteHeader: false, + statusCode: 200, + headers: nil, } - core.StoreInFlightReqData( - inFlightReqID, - &vault.InFlightReqData { - StartTime: time.Now(), - ClientRemoteAddr: r.RemoteAddr, - ReqPath: r.URL.Path, - }) - // deleting the in-flight request entry - defer core.DeleteInFlightReqData(inFlightReqID) // This block needs to be here so that upon sending SIGHUP, custom response // headers are also reloaded into the handlers. @@ -419,16 +427,14 @@ func wrapGenericHandler(core *vault.Core, h http.Handler, props *vault.HandlerPr la := props.ListenerConfig.Address listenerCustomHeaders := core.GetListenerCustomResponseHeaders(la) if listenerCustomHeaders != nil { - w = &statusHeaderResponseWriter{ - wrapped: w, - logger: core.Logger(), - wroteHeader: false, - statusCode: 200, - headers: listenerCustomHeaders.StatusCodeHeaderMap, - } + newResponseWriter, _ := w.(WrappingResponseWriter) + newResponseWriter.SetHeaders(listenerCustomHeaders.StatusCodeHeaderMap) } } + // saving start time for the in-flight requests + inFlightReqStartTime := time.Now() + // Set the Cache-Control header for all the responses returned // by Vault w.Header().Set("Cache-Control", "no-store") @@ -480,6 +486,44 @@ func wrapGenericHandler(core *vault.Core, h http.Handler, props *vault.HandlerPr return } + // The uuid for the request is going to be generated when a logical + // request is generated. But, here we generate one to be able to track + // in-flight requests, and use that to update the req data with clientID + inFlightReqID, err := uuid.GenerateUUID() + if err != nil { + respondError(w, http.StatusInternalServerError, fmt.Errorf("failed to generate an identifier for the in-flight request")) + } + // adding an entry to the context to enable updating in-flight + // data with ClientID in the logical layer + r = r.WithContext(context.WithValue(r.Context(), "in-flight-reqID", inFlightReqID)) + + // extracting the client address to be included in the in-flight request + var clientAddr string + headers, headersOK := r.Header[textproto.CanonicalMIMEHeaderKey("X-Forwarded-For")] + if !headersOK || len(headers) == 0 { + clientAddr = r.RemoteAddr + }else { + clientAddr = headers[0] + } + + // getting the request method + requestMethod := r.Method + + // Storing the in-flight requests. Path should include namespace as well + core.StoreInFlightReqData( + inFlightReqID, + &vault.InFlightReqData { + StartTime: inFlightReqStartTime, + ReqPath: r.URL.Path, + ClientRemoteAddr: clientAddr, + Method: requestMethod, + }) + defer func() { + // Not expecting this fail, so skipping the assertion check + newResponseWriter, _ := w.(WrappingResponseWriter) + core.FinalizeInFlightReqData(inFlightReqID, newResponseWriter.StatusCode()) + }() + // Setting the namespace in the header to be included in the error message ns := r.Header.Get(consts.NamespaceHeaderName) if ns != "" { diff --git a/http/sys_in_flight_requests.go b/http/sys_in_flight_requests.go index f28da766d2fb..4c72caca70aa 100644 --- a/http/sys_in_flight_requests.go +++ b/http/sys_in_flight_requests.go @@ -19,7 +19,7 @@ func handleUnAuthenticatedInFlightRequest(core *vault.Core) http.Handler { } now := time.Now() - currentInFlightReqMap := core.GetInFlightReqData() + currentInFlightReqMap := core.LoadInFlightReqData() for _, v := range currentInFlightReqMap { v.SnapshotTime = now diff --git a/sdk/logical/response.go b/sdk/logical/response.go index a6751125394b..68fd0561d60c 100644 --- a/sdk/logical/response.go +++ b/sdk/logical/response.go @@ -192,6 +192,12 @@ func RespondWithStatusCode(resp *Response, req *Request, code int) (*Response, e return ret, nil } +type WrappingResponseWriter interface { + http.ResponseWriter + Wrapped() http.ResponseWriter + StatusCode() int +} + // HTTPResponseWriter is optionally added to a request object and can be used to // write directly to the HTTP response writer. type HTTPResponseWriter struct { @@ -202,9 +208,19 @@ type HTTPResponseWriter struct { // NewHTTPResponseWriter creates a new HTTPResponseWriter object that wraps the // provided io.Writer. func NewHTTPResponseWriter(w http.ResponseWriter) *HTTPResponseWriter { - return &HTTPResponseWriter{ - ResponseWriter: w, - written: new(uint32), + // FIXME: this is a band aid and not a good solution, just put it here + // to make the tests pass + newR, ok := w.(WrappingResponseWriter) + if ok { + return &HTTPResponseWriter{ + ResponseWriter: newR.Wrapped(), + written: new(uint32), + } + }else { + return &HTTPResponseWriter{ + ResponseWriter: w, + written: new(uint32), + } } } diff --git a/vault/core.go b/vault/core.go index b10e80d97951..8e0f4f7ece2d 100644 --- a/vault/core.go +++ b/vault/core.go @@ -389,6 +389,9 @@ type Core struct { // disabled physicalCache physical.ToggleablePurgemonster + // enableLogRequest indicates whether logging requests are enabled + logRequestsEnabled bool + // reloadFuncs is a map containing reload functions reloadFuncs map[string][]reloadutil.ReloadFunc @@ -1033,6 +1036,8 @@ func NewCore(conf *CoreConfig) (*Core, error) { c.customListenerHeader.Store(([]*ListenerCustomHeaders)(nil)) } + c.logRequestsEnabled = conf.RawConfig.EnableLogRequests + quotasLogger := conf.Logger.Named("quotas") c.allLoggers = append(c.allLoggers, quotasLogger) c.quotaManager, err = quotas.NewManager(quotasLogger, c.quotaLeaseWalker, c.metricSink) @@ -2954,22 +2959,31 @@ type InFlightReqData struct { StartTime time.Time `json:"start_time"` ClientRemoteAddr string `json:"client_remote_address"` ReqPath string `json:"request_path"` + Method string `json:"request_method"` + ClientID string `json:"client_id"` SnapshotTime time.Time `json:"snapshot_time"` } func (c *Core) StoreInFlightReqData(reqID string, data *InFlightReqData) { c.inFlightReqData.InFlightReqMap.Store(reqID, data) c.inFlightReqData.InFlightReqCount.Inc() - } -func (c *Core) DeleteInFlightReqData(reqID string) { +// FinalizeInFlightReqData is going log the completed request if the +// corresponding server config option is enabled. It also removes the +// request from the inFlightReqMap and decrement the number of in-flight +// requests by one. +func (c *Core) FinalizeInFlightReqData(reqID string, statusCode int) { + if c.logRequestsEnabled { + c.LogCompletedRequests(reqID, statusCode) + } c.inFlightReqData.InFlightReqMap.Delete(reqID) c.inFlightReqData.InFlightReqCount.Dec() } -func (c *Core) GetInFlightReqData() map[string]*InFlightReqData { - +// LoadInFlightReqData creates a snapshot map of the current +// in-flight requests +func (c *Core) LoadInFlightReqData() map[string]*InFlightReqData { currentInFlightReqMap := make(map[string]*InFlightReqData) c.inFlightReqData.InFlightReqMap.Range(func(key, value interface{}) bool { // there is only one writer to this map, so skip checking for errors @@ -2980,4 +2994,37 @@ func (c *Core) GetInFlightReqData() map[string]*InFlightReqData { }) return currentInFlightReqMap -} \ No newline at end of file +} + +// UpdateInFlightReqData updates the data for a specific reqID with +// the clientID +func (c *Core) UpdateInFlightReqData(reqID, clientID string) { + v, ok := c.inFlightReqData.InFlightReqMap.Load(reqID) + if !ok { + c.Logger().Trace("failed to retrieve request with ID %v", reqID) + return + } + reqData, _ := v.(*InFlightReqData) + reqData.ClientID = clientID + c.inFlightReqData.InFlightReqMap.Store(reqID, reqData) +} + +// LogCompletedRequests Logs the completed request to the server logs +func (c *Core) LogCompletedRequests(reqID string, statusCode int) { + v, ok := c.inFlightReqData.InFlightReqMap.Load(reqID) + if !ok { + c.Logger().Trace("failed to retrieve request with ID %v", reqID) + return + } + // there is only one writer to this map, so skip checking for errors + reqData, _ := v.(*InFlightReqData) + c.Logger().Trace("completed_request","client_id", reqData.ClientID, "client_address", reqData.ClientRemoteAddr, "status_code", statusCode, "request_path", reqData.ReqPath, "request_method", reqData.Method) +} + +func (c *Core) SetLogRequests(){ + conf := c.rawConfig.Load() + if conf == nil { + return + } + c.logRequestsEnabled = conf.(*server.Config).EnableLogRequests +} diff --git a/vault/logical_system.go b/vault/logical_system.go index e7725cb253c6..941f7390ad21 100644 --- a/vault/logical_system.go +++ b/vault/logical_system.go @@ -2980,7 +2980,7 @@ func (b *SystemBackend) handleInFlightRequestData(_ context.Context, req *logica } now := time.Now() - currentInFlightReqMap := b.Core.GetInFlightReqData() + currentInFlightReqMap := b.Core.LoadInFlightReqData() for _, v := range currentInFlightReqMap { v.SnapshotTime = now diff --git a/vault/request_handling.go b/vault/request_handling.go index c83bac2dbd21..f1089d8026a2 100644 --- a/vault/request_handling.go +++ b/vault/request_handling.go @@ -439,7 +439,12 @@ func (c *Core) switchedLockHandleRequest(httpCtx context.Context, req *logical.R return nil, fmt.Errorf("could not parse namespace from http context: %w", err) } - resp, err = c.handleCancelableRequest(namespace.ContextWithNamespace(ctx, ns), req) + ctx = namespace.ContextWithNamespace(ctx, ns) + inFlightReqID, ok := httpCtx.Value("in-flight-reqID").(string) + if ok { + ctx = context.WithValue(ctx, "in-flight-reqID", inFlightReqID) + } + resp, err = c.handleCancelableRequest(ctx, req) req.SetTokenEntry(nil) cancel() @@ -772,6 +777,17 @@ func (c *Core) handleRequest(ctx context.Context, req *logical.Request) (retResp return nil, nil, ctErr } + // Updating in-flight request data with client/entity ID + inFlightReqID, ok := ctx.Value("in-flight-reqID").(string) + if ok { + switch { + case req.ClientID != "": + c.UpdateInFlightReqData(inFlightReqID, req.ClientID) + case req.EntityID != "": + c.UpdateInFlightReqData(inFlightReqID, req.EntityID) + } + } + // We run this logic first because we want to decrement the use count even // in the case of an error (assuming we can successfully look up; if we // need to forward, we exit before now) diff --git a/vault/testing.go b/vault/testing.go index 6ba933e85d99..9b3dc9dd59fe 100644 --- a/vault/testing.go +++ b/vault/testing.go @@ -130,6 +130,7 @@ func TestCoreWithSeal(t testing.T, testSeal Seal, enableRaw bool) *Core { func TestCoreWithCustomResponseHeaderAndUI(t testing.T, CustomResponseHeaders map[string]map[string]string, enableUI bool) (*Core, [][]byte, string) { confRaw := &server.Config{ + EnableLogRequests: true, SharedConfig: &configutil.SharedConfig{ Listeners: []*configutil.Listener{ { From 5914acd902c6190c8e6c9b68d545bade52037d4a Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Wed, 17 Nov 2021 22:19:11 -0800 Subject: [PATCH 10/33] fixing a test --- http/handler.go | 13 +++---------- http/sys_config_state_test.go | 1 + 2 files changed, 4 insertions(+), 10 deletions(-) diff --git a/http/handler.go b/http/handler.go index 553fc8301f27..1e4035519953 100644 --- a/http/handler.go +++ b/http/handler.go @@ -20,7 +20,6 @@ import ( "regexp" "strconv" "strings" - "sync/atomic" "time" "github.com/NYTimes/gziphandler" @@ -234,16 +233,9 @@ type statusHeaderResponseWriter struct { logger log.Logger wroteHeader bool statusCode int - written *uint32 headers map[string][]*vault.CustomHeader } - -// Written tells us if the writer has been written to yet. -func (w *statusHeaderResponseWriter) Written() bool { - return atomic.LoadUint32(w.written) == 1 -} - func (w *statusHeaderResponseWriter) StatusCode() int { return w.statusCode } @@ -427,8 +419,9 @@ func wrapGenericHandler(core *vault.Core, h http.Handler, props *vault.HandlerPr la := props.ListenerConfig.Address listenerCustomHeaders := core.GetListenerCustomResponseHeaders(la) if listenerCustomHeaders != nil { - newResponseWriter, _ := w.(WrappingResponseWriter) - newResponseWriter.SetHeaders(listenerCustomHeaders.StatusCodeHeaderMap) + nw, _ := w.(WrappingResponseWriter) + nw.SetHeaders(listenerCustomHeaders.StatusCodeHeaderMap) + w = nw } } diff --git a/http/sys_config_state_test.go b/http/sys_config_state_test.go index 543809ce2bd5..c90df10a08ad 100644 --- a/http/sys_config_state_test.go +++ b/http/sys_config_state_test.go @@ -48,6 +48,7 @@ func TestSysConfigState_Sanitized(t *testing.T) { "plugin_directory": "", "enable_response_header_hostname": false, "enable_response_header_raft_node_id": false, + "enable_log_requests": false, } expected = map[string]interface{}{ From f418b0e529c8e5fb123b3a0f77b6444fa572cc05 Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Thu, 18 Nov 2021 10:43:12 -0800 Subject: [PATCH 11/33] providing log_requests_info as a config option to determine at which level requests should be logged --- command/server.go | 2 +- command/server/config.go | 19 +++++++------- command/server/config_test_helpers.go | 2 +- command/server/test-fixtures/config3.hcl | 2 +- http/sys_config_state_test.go | 2 +- vault/core.go | 33 ++++++++++++++++++------ vault/testing.go | 2 +- 7 files changed, 39 insertions(+), 23 deletions(-) diff --git a/command/server.go b/command/server.go index 53cb97779713..5098f300f816 100644 --- a/command/server.go +++ b/command/server.go @@ -1548,7 +1548,7 @@ func (c *ServerCommand) Run(args []string) int { } // Setting log request with the new value in the config after reload - core.SetLogRequests() + core.ReloadLogRequestsInfo() if config.LogLevel != "" { configLogLevel := strings.ToLower(strings.TrimSpace(config.LogLevel)) diff --git a/command/server/config.go b/command/server/config.go index b55e5eddaa46..bb615bf7da74 100644 --- a/command/server/config.go +++ b/command/server/config.go @@ -77,8 +77,8 @@ type Config struct { EnableResponseHeaderHostname bool `hcl:"-"` EnableResponseHeaderHostnameRaw interface{} `hcl:"enable_response_header_hostname"` - EnableLogRequests bool `hcl:"-"` - EnableLogRequestsRaw interface{} `hcl:"enable_log_requests"` + LogRequestsInfo string `hcl:"-"` + LogRequestsInfoRaw interface{} `hcl:"log_requests_info"` EnableResponseHeaderRaftNodeID bool `hcl:"-"` EnableResponseHeaderRaftNodeIDRaw interface{} `hcl:"enable_response_header_raft_node_id"` @@ -295,9 +295,9 @@ func (c *Config) Merge(c2 *Config) *Config { result.EnableResponseHeaderHostname = c2.EnableResponseHeaderHostname } - result.EnableLogRequests = c.EnableLogRequests - if c2.EnableLogRequests { - result.EnableLogRequests = c2.EnableLogRequests + result.LogRequestsInfo = c.LogRequestsInfo + if c2.LogRequestsInfo != "" { + result.LogRequestsInfo = c2.LogRequestsInfo } result.EnableResponseHeaderRaftNodeID = c.EnableResponseHeaderRaftNodeID @@ -488,10 +488,9 @@ func ParseConfig(d, source string) (*Config, error) { } } - if result.EnableLogRequestsRaw != nil { - if result.EnableLogRequests, err = parseutil.ParseBool(result.EnableLogRequestsRaw); err != nil { - return nil, err - } + if result.LogRequestsInfoRaw != nil { + result.LogRequestsInfo = strings.ToLower(result.LogRequestsInfoRaw.(string)) + result.LogRequestsInfoRaw = "" } if result.EnableResponseHeaderRaftNodeIDRaw != nil { @@ -855,7 +854,7 @@ func (c *Config) Sanitized() map[string]interface{} { "enable_response_header_raft_node_id": c.EnableResponseHeaderRaftNodeID, - "enable_log_requests": c.EnableLogRequests, + "log_requests_info": c.LogRequestsInfo, } for k, v := range sharedResult { result[k] = v diff --git a/command/server/config_test_helpers.go b/command/server/config_test_helpers.go index df3171074a0e..b09881260290 100644 --- a/command/server/config_test_helpers.go +++ b/command/server/config_test_helpers.go @@ -701,7 +701,7 @@ func testConfig_Sanitized(t *testing.T) { "enable_ui": true, "enable_response_header_hostname": false, "enable_response_header_raft_node_id": false, - "enable_log_requests": true, + "log_requests_info": "basic", "ha_storage": map[string]interface{}{ "cluster_addr": "top_level_cluster_addr", "disable_clustering": true, diff --git a/command/server/test-fixtures/config3.hcl b/command/server/test-fixtures/config3.hcl index 659d0897fb0f..9de5c83d46bb 100644 --- a/command/server/test-fixtures/config3.hcl +++ b/command/server/test-fixtures/config3.hcl @@ -1,6 +1,6 @@ disable_cache = true disable_mlock = true -enable_log_requests = true +log_requests_info = "Basic" ui = true diff --git a/http/sys_config_state_test.go b/http/sys_config_state_test.go index c90df10a08ad..ea34296a47bd 100644 --- a/http/sys_config_state_test.go +++ b/http/sys_config_state_test.go @@ -48,7 +48,7 @@ func TestSysConfigState_Sanitized(t *testing.T) { "plugin_directory": "", "enable_response_header_hostname": false, "enable_response_header_raft_node_id": false, - "enable_log_requests": false, + "log_requests_info": "", } expected = map[string]interface{}{ diff --git a/vault/core.go b/vault/core.go index 8e0f4f7ece2d..83df58bf4ff3 100644 --- a/vault/core.go +++ b/vault/core.go @@ -389,8 +389,8 @@ type Core struct { // disabled physicalCache physical.ToggleablePurgemonster - // enableLogRequest indicates whether logging requests are enabled - logRequestsEnabled bool + // logRequestsInfo indicates at which level requests should be logged + logRequestsInfo string // reloadFuncs is a map containing reload functions reloadFuncs map[string][]reloadutil.ReloadFunc @@ -1036,7 +1036,7 @@ func NewCore(conf *CoreConfig) (*Core, error) { c.customListenerHeader.Store(([]*ListenerCustomHeaders)(nil)) } - c.logRequestsEnabled = conf.RawConfig.EnableLogRequests + c.logRequestsInfo = conf.RawConfig.LogRequestsInfo quotasLogger := conf.Logger.Named("quotas") c.allLoggers = append(c.allLoggers, quotasLogger) @@ -2974,7 +2974,7 @@ func (c *Core) StoreInFlightReqData(reqID string, data *InFlightReqData) { // request from the inFlightReqMap and decrement the number of in-flight // requests by one. func (c *Core) FinalizeInFlightReqData(reqID string, statusCode int) { - if c.logRequestsEnabled { + if c.logRequestsInfo != "" { c.LogCompletedRequests(reqID, statusCode) } c.inFlightReqData.InFlightReqMap.Delete(reqID) @@ -3009,22 +3009,39 @@ func (c *Core) UpdateInFlightReqData(reqID, clientID string) { c.inFlightReqData.InFlightReqMap.Store(reqID, reqData) } +func (c *Core) logRequests(msg string, args ...interface{}) { + switch c.logRequestsInfo { + case "error": + c.Logger().Error(msg, args...) + case "warn": + c.Logger().Warn(msg, args...) + case "basic": + fallthrough + case "info": + c.Logger().Info(msg, args...) + case "debug": + c.Logger().Debug(msg, args...) + case "trace": + c.Logger().Trace(msg, args...) + } +} + // LogCompletedRequests Logs the completed request to the server logs func (c *Core) LogCompletedRequests(reqID string, statusCode int) { v, ok := c.inFlightReqData.InFlightReqMap.Load(reqID) if !ok { - c.Logger().Trace("failed to retrieve request with ID %v", reqID) + c.logRequests(fmt.Sprintf("failed to retrieve request with ID %v", reqID)) return } // there is only one writer to this map, so skip checking for errors reqData, _ := v.(*InFlightReqData) - c.Logger().Trace("completed_request","client_id", reqData.ClientID, "client_address", reqData.ClientRemoteAddr, "status_code", statusCode, "request_path", reqData.ReqPath, "request_method", reqData.Method) + c.logRequests("completed_request","client_id", reqData.ClientID, "client_address", reqData.ClientRemoteAddr, "status_code", statusCode, "request_path", reqData.ReqPath, "request_method", reqData.Method) } -func (c *Core) SetLogRequests(){ +func (c *Core) ReloadLogRequestsInfo(){ conf := c.rawConfig.Load() if conf == nil { return } - c.logRequestsEnabled = conf.(*server.Config).EnableLogRequests + c.logRequestsInfo = conf.(*server.Config).LogRequestsInfo } diff --git a/vault/testing.go b/vault/testing.go index 9b3dc9dd59fe..365bf9fa61e3 100644 --- a/vault/testing.go +++ b/vault/testing.go @@ -130,7 +130,7 @@ func TestCoreWithSeal(t testing.T, testSeal Seal, enableRaw bool) *Core { func TestCoreWithCustomResponseHeaderAndUI(t testing.T, CustomResponseHeaders map[string]map[string]string, enableUI bool) (*Core, [][]byte, string) { confRaw := &server.Config{ - EnableLogRequests: true, + LogRequestsInfo: "basic", SharedConfig: &configutil.SharedConfig{ Listeners: []*configutil.Listener{ { From c181d152dd3bb6843eec83f345fa0af17416a86f Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Thu, 18 Nov 2021 12:56:31 -0800 Subject: [PATCH 12/33] removing a member and a method from the StatusHeaderResponseWriter struct --- http/handler.go | 30 +++++++++--------------------- sdk/logical/response.go | 1 - 2 files changed, 9 insertions(+), 22 deletions(-) diff --git a/http/handler.go b/http/handler.go index 1e4035519953..757d8f1d8437 100644 --- a/http/handler.go +++ b/http/handler.go @@ -25,7 +25,6 @@ import ( "github.com/NYTimes/gziphandler" "github.com/hashicorp/errwrap" "github.com/hashicorp/go-cleanhttp" - log "github.com/hashicorp/go-hclog" "github.com/hashicorp/go-secure-stdlib/parseutil" "github.com/hashicorp/go-sockaddr" "github.com/hashicorp/vault/helper/namespace" @@ -224,22 +223,15 @@ func Handler(props *vault.HandlerProperties) http.Handler { type WrappingResponseWriter interface { http.ResponseWriter Wrapped() http.ResponseWriter - StatusCode() int - SetHeaders(h map[string][]*vault.CustomHeader) } type statusHeaderResponseWriter struct { wrapped http.ResponseWriter - logger log.Logger wroteHeader bool statusCode int headers map[string][]*vault.CustomHeader } -func (w *statusHeaderResponseWriter) StatusCode() int { - return w.statusCode -} - func (w *statusHeaderResponseWriter) SetHeaders(h map[string][]*vault.CustomHeader) { w.headers = h } @@ -405,9 +397,8 @@ func wrapGenericHandler(core *vault.Core, h http.Handler, props *vault.HandlerPr return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - w = &statusHeaderResponseWriter{ + nw := &statusHeaderResponseWriter{ wrapped: w, - logger: core.Logger(), wroteHeader: false, statusCode: 200, headers: nil, @@ -419,9 +410,7 @@ func wrapGenericHandler(core *vault.Core, h http.Handler, props *vault.HandlerPr la := props.ListenerConfig.Address listenerCustomHeaders := core.GetListenerCustomResponseHeaders(la) if listenerCustomHeaders != nil { - nw, _ := w.(WrappingResponseWriter) nw.SetHeaders(listenerCustomHeaders.StatusCodeHeaderMap) - w = nw } } @@ -430,7 +419,7 @@ func wrapGenericHandler(core *vault.Core, h http.Handler, props *vault.HandlerPr // Set the Cache-Control header for all the responses returned // by Vault - w.Header().Set("Cache-Control", "no-store") + nw.Header().Set("Cache-Control", "no-store") // Start with the request context ctx := r.Context() @@ -454,12 +443,12 @@ func wrapGenericHandler(core *vault.Core, h http.Handler, props *vault.HandlerPr if core.RaftNodeIDHeaderEnabled() { nodeID := core.GetRaftNodeID() if nodeID != "" { - w.Header().Set("X-Vault-Raft-Node-ID", nodeID) + nw.Header().Set("X-Vault-Raft-Node-ID", nodeID) } } if core.HostnameHeaderEnabled() && hostname != "" { - w.Header().Set("X-Vault-Hostname", hostname) + nw.Header().Set("X-Vault-Hostname", hostname) } switch { @@ -474,7 +463,7 @@ func wrapGenericHandler(core *vault.Core, h http.Handler, props *vault.HandlerPr case strings.HasPrefix(r.URL.Path, "/ui"), r.URL.Path == "/robots.txt", r.URL.Path == "/": default: - respondError(w, http.StatusNotFound, nil) + respondError(nw, http.StatusNotFound, nil) cancelFunc() return } @@ -484,7 +473,7 @@ func wrapGenericHandler(core *vault.Core, h http.Handler, props *vault.HandlerPr // in-flight requests, and use that to update the req data with clientID inFlightReqID, err := uuid.GenerateUUID() if err != nil { - respondError(w, http.StatusInternalServerError, fmt.Errorf("failed to generate an identifier for the in-flight request")) + respondError(nw, http.StatusInternalServerError, fmt.Errorf("failed to generate an identifier for the in-flight request")) } // adding an entry to the context to enable updating in-flight // data with ClientID in the logical layer @@ -513,17 +502,16 @@ func wrapGenericHandler(core *vault.Core, h http.Handler, props *vault.HandlerPr }) defer func() { // Not expecting this fail, so skipping the assertion check - newResponseWriter, _ := w.(WrappingResponseWriter) - core.FinalizeInFlightReqData(inFlightReqID, newResponseWriter.StatusCode()) + core.FinalizeInFlightReqData(inFlightReqID, nw.statusCode) }() // Setting the namespace in the header to be included in the error message ns := r.Header.Get(consts.NamespaceHeaderName) if ns != "" { - w.Header().Set(consts.NamespaceHeaderName, ns) + nw.Header().Set(consts.NamespaceHeaderName, ns) } - h.ServeHTTP(w, r) + h.ServeHTTP(nw, r) cancelFunc() return diff --git a/sdk/logical/response.go b/sdk/logical/response.go index 68fd0561d60c..631f85f40c03 100644 --- a/sdk/logical/response.go +++ b/sdk/logical/response.go @@ -195,7 +195,6 @@ func RespondWithStatusCode(resp *Response, req *Request, code int) (*Response, e type WrappingResponseWriter interface { http.ResponseWriter Wrapped() http.ResponseWriter - StatusCode() int } // HTTPResponseWriter is optionally added to a request object and can be used to From 16ed14a393f172a6539a09ccc993dd36b377094f Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Fri, 19 Nov 2021 11:16:22 -0800 Subject: [PATCH 13/33] adding api docks --- command/server/config.go | 2 +- http/sys_in_flight_requests.go | 6 --- vault/core.go | 16 +++++--- vault/logical_system.go | 5 --- .../content/api-docs/system/in-flight-req.mdx | 41 +++++++++++++++++++ website/data/api-docs-nav-data.json | 4 ++ 6 files changed, 57 insertions(+), 17 deletions(-) create mode 100644 website/content/api-docs/system/in-flight-req.mdx diff --git a/command/server/config.go b/command/server/config.go index bb615bf7da74..93cc9c34f7e7 100644 --- a/command/server/config.go +++ b/command/server/config.go @@ -489,7 +489,7 @@ func ParseConfig(d, source string) (*Config, error) { } if result.LogRequestsInfoRaw != nil { - result.LogRequestsInfo = strings.ToLower(result.LogRequestsInfoRaw.(string)) + result.LogRequestsInfo = strings.ToLower(strings.TrimSpace(result.LogRequestsInfoRaw.(string))) result.LogRequestsInfoRaw = "" } diff --git a/http/sys_in_flight_requests.go b/http/sys_in_flight_requests.go index 4c72caca70aa..82da072cedf1 100644 --- a/http/sys_in_flight_requests.go +++ b/http/sys_in_flight_requests.go @@ -4,7 +4,6 @@ import ( "encoding/json" "fmt" "net/http" - "time" "github.com/hashicorp/vault/vault" ) @@ -17,14 +16,9 @@ func handleUnAuthenticatedInFlightRequest(core *vault.Core) http.Handler { respondError(w, http.StatusMethodNotAllowed, nil) return } - now := time.Now() currentInFlightReqMap := core.LoadInFlightReqData() - for _, v := range currentInFlightReqMap { - v.SnapshotTime = now - } - content, err := json.Marshal(currentInFlightReqMap) if err != nil { respondError(w, http.StatusInternalServerError, fmt.Errorf("error while marshalling the in-flight requests data: %w", err)) diff --git a/vault/core.go b/vault/core.go index 83df58bf4ff3..1d09107adaa5 100644 --- a/vault/core.go +++ b/vault/core.go @@ -1036,7 +1036,11 @@ func NewCore(conf *CoreConfig) (*Core, error) { c.customListenerHeader.Store(([]*ListenerCustomHeaders)(nil)) } - c.logRequestsInfo = conf.RawConfig.LogRequestsInfo + if log.LevelFromString(conf.RawConfig.LogRequestsInfo) > 0 { + c.logRequestsInfo = conf.RawConfig.LogRequestsInfo + } else { + c.logger.Warn("invalid log_requests_info", "level", conf.RawConfig.LogRequestsInfo) + } quotasLogger := conf.Logger.Named("quotas") c.allLoggers = append(c.allLoggers, quotasLogger) @@ -2961,7 +2965,6 @@ type InFlightReqData struct { ReqPath string `json:"request_path"` Method string `json:"request_method"` ClientID string `json:"client_id"` - SnapshotTime time.Time `json:"snapshot_time"` } func (c *Core) StoreInFlightReqData(reqID string, data *InFlightReqData) { @@ -3015,8 +3018,6 @@ func (c *Core) logRequests(msg string, args ...interface{}) { c.Logger().Error(msg, args...) case "warn": c.Logger().Warn(msg, args...) - case "basic": - fallthrough case "info": c.Logger().Info(msg, args...) case "debug": @@ -3043,5 +3044,10 @@ func (c *Core) ReloadLogRequestsInfo(){ if conf == nil { return } - c.logRequestsInfo = conf.(*server.Config).LogRequestsInfo + infoLevel := conf.(*server.Config).LogRequestsInfo + if log.LevelFromString(infoLevel) > 0 { + c.logRequestsInfo = infoLevel + }else { + c.logger.Warn("invalid log_requests_info", "level", infoLevel) + } } diff --git a/vault/logical_system.go b/vault/logical_system.go index 941f7390ad21..1b12de4705a7 100644 --- a/vault/logical_system.go +++ b/vault/logical_system.go @@ -2979,13 +2979,8 @@ func (b *SystemBackend) handleInFlightRequestData(_ context.Context, req *logica }, } - now := time.Now() currentInFlightReqMap := b.Core.LoadInFlightReqData() - for _, v := range currentInFlightReqMap { - v.SnapshotTime = now - } - content, err := json.Marshal(currentInFlightReqMap) if err != nil { resp.Data[logical.HTTPRawBody] = fmt.Sprintf("error while marshalling the in-flight requests data: %s", err) diff --git a/website/content/api-docs/system/in-flight-req.mdx b/website/content/api-docs/system/in-flight-req.mdx new file mode 100644 index 000000000000..aa5b4f62a898 --- /dev/null +++ b/website/content/api-docs/system/in-flight-req.mdx @@ -0,0 +1,41 @@ +--- +layout: api +page_title: /sys/in-flight-req - HTTP API +description: The `/sys/in-flight-req` endpoint is used to get information on in-flight requests. +--- + +# `/sys/in-flight-req` + +The `/sys/in-flight-req` endpoint is used to get information on in-flight requests. +The returned information contains the `start_time`, `client_remote_address`, `request_path`, +`request_method`, and `client_id` of the in-flight requests. + +## Collect In-Flight Request Information + +This endpoint returns the information about the in-flight requests. + +| Method | Path | +| :----- | :---------- | +| `GET` | `/sys/in-flight-req` | + +### Sample Request + +```shell-session +$ curl \ + --header "X-Vault-Token: ..." \ + http://127.0.0.1:8200/v1/sys/in-flight-req +``` + +### Sample Response + +```json +{ + "9049326b-ceed-1033-c099-96c5cc97db1f": { + "start_time": "2021-11-19T09:13:01.34157-08:00", + "client_remote_address": "127.0.0.3:49816", + "request_path": "/v1/sys/in-flight-req", + "request_method": "GET", + "client_id": "", + } +} +``` diff --git a/website/data/api-docs-nav-data.json b/website/data/api-docs-nav-data.json index 0a5a0e06e230..62717b6813b7 100644 --- a/website/data/api-docs-nav-data.json +++ b/website/data/api-docs-nav-data.json @@ -393,6 +393,10 @@ "title": "/sys/host-info", "path": "system/host-info" }, + { + "title": "/sys/in-flight-req", + "path": "system/in-flight-req" + }, { "title": "/sys/init", "path": "system/init" From d7682a5026736a8c3525e3a2791b89da5f153fe8 Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Tue, 23 Nov 2021 13:46:24 -0800 Subject: [PATCH 14/33] revert changes in NewHTTPResponseWriter --- sdk/logical/response.go | 16 +++------------- 1 file changed, 3 insertions(+), 13 deletions(-) diff --git a/sdk/logical/response.go b/sdk/logical/response.go index 425332dd95fd..e8276c789ace 100644 --- a/sdk/logical/response.go +++ b/sdk/logical/response.go @@ -203,19 +203,9 @@ type HTTPResponseWriter struct { // NewHTTPResponseWriter creates a new HTTPResponseWriter object that wraps the // provided io.Writer. func NewHTTPResponseWriter(w http.ResponseWriter) *HTTPResponseWriter { - // FIXME: this is a band aid and not a good solution, just put it here - // to make the tests pass - newR, ok := w.(WrappingResponseWriter) - if ok { - return &HTTPResponseWriter{ - ResponseWriter: newR.Wrapped(), - written: new(uint32), - } - }else { - return &HTTPResponseWriter{ - ResponseWriter: w, - written: new(uint32), - } + return &HTTPResponseWriter{ + ResponseWriter: w, + written: new(uint32), } } From 2ad56c292528b84a66ba698974a483ea1332e18a Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Tue, 23 Nov 2021 14:57:57 -0800 Subject: [PATCH 15/33] Fix logging invalid log_requests_info value --- vault/core.go | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/vault/core.go b/vault/core.go index 61b8a213e890..278eeeefafcf 100644 --- a/vault/core.go +++ b/vault/core.go @@ -1038,9 +1038,10 @@ func NewCore(conf *CoreConfig) (*Core, error) { c.customListenerHeader.Store(([]*ListenerCustomHeaders)(nil)) } - if log.LevelFromString(conf.RawConfig.LogRequestsInfo) > 0 { + switch { + case log.LevelFromString(conf.RawConfig.LogRequestsInfo) > 0: c.logRequestsInfo = conf.RawConfig.LogRequestsInfo - } else { + case conf.RawConfig.LogRequestsInfo != "": c.logger.Warn("invalid log_requests_info", "level", conf.RawConfig.LogRequestsInfo) } @@ -3055,9 +3056,10 @@ func (c *Core) ReloadLogRequestsInfo(){ return } infoLevel := conf.(*server.Config).LogRequestsInfo - if log.LevelFromString(infoLevel) > 0 { + switch { + case log.LevelFromString(infoLevel) > 0: c.logRequestsInfo = infoLevel - }else { + case infoLevel != "": c.logger.Warn("invalid log_requests_info", "level", infoLevel) } } From 814128b96a929e95ac85a4cfc697675361ee89b8 Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Wed, 24 Nov 2021 15:29:41 -0800 Subject: [PATCH 16/33] Addressing comments --- http/handler.go | 10 +-- http/handler_test.go | 73 ++----------------- http/sys_in_flight_requests.go | 12 +-- ...test.go => sys_in_flight_requests_test.go} | 2 +- internalshared/configutil/listener.go | 23 ++++-- sdk/logical/request.go | 6 ++ vault/core.go | 23 +----- vault/request_handling.go | 22 +++--- website/content/docs/internals/telemetry.mdx | 2 +- 9 files changed, 54 insertions(+), 119 deletions(-) rename http/{sys_in_flight_reqeusts_test.go => sys_in_flight_requests_test.go} (94%) diff --git a/http/handler.go b/http/handler.go index a1c5e6de4a0c..9bea2fb542b0 100644 --- a/http/handler.go +++ b/http/handler.go @@ -6,7 +6,6 @@ import ( "encoding/json" "errors" "fmt" - "github.com/hashicorp/go-uuid" "io" "io/fs" "io/ioutil" @@ -26,6 +25,7 @@ import ( "github.com/hashicorp/go-cleanhttp" "github.com/hashicorp/go-secure-stdlib/parseutil" "github.com/hashicorp/go-sockaddr" + "github.com/hashicorp/go-uuid" "github.com/hashicorp/vault/helper/namespace" "github.com/hashicorp/vault/internalshared/configutil" "github.com/hashicorp/vault/sdk/helper/consts" @@ -195,7 +195,7 @@ func Handler(props *vault.HandlerProperties) http.Handler { mux.Handle("/v1/sys/pprof/", handleLogicalNoForward(core)) } - if props.ListenerConfig != nil && props.ListenerConfig.Profiling.UnauthenticatedInFlightAccess { + if props.ListenerConfig != nil && props.ListenerConfig.InFlightRequestLogging.UnauthenticatedInFlightAccess { mux.Handle("/v1/sys/in-flight-req", handleUnAuthenticatedInFlightRequest(core)) } else { mux.Handle("/v1/sys/in-flight-req", handleLogicalNoForward(core)) @@ -385,12 +385,12 @@ func wrapGenericHandler(core *vault.Core, h http.Handler, props *vault.HandlerPr } // adding an entry to the context to enable updating in-flight // data with ClientID in the logical layer - r = r.WithContext(context.WithValue(r.Context(), "in-flight-reqID", inFlightReqID)) + r = r.WithContext(context.WithValue(r.Context(), logical.CtxKeyInFlightRequestID{}, inFlightReqID)) // extracting the client address to be included in the in-flight request var clientAddr string - headers, headersOK := r.Header[textproto.CanonicalMIMEHeaderKey("X-Forwarded-For")] - if !headersOK || len(headers) == 0 { + headers := r.Header[textproto.CanonicalMIMEHeaderKey("X-Forwarded-For")] + if len(headers) == 0 { clientAddr = r.RemoteAddr }else { clientAddr = headers[0] diff --git a/http/handler_test.go b/http/handler_test.go index 91f72f72476e..999a776c7489 100644 --- a/http/handler_test.go +++ b/http/handler_test.go @@ -11,7 +11,6 @@ import ( "net/textproto" "net/url" "reflect" - "strconv" "strings" "testing" "time" @@ -321,73 +320,15 @@ func TestHandler_InFlightRequest(t *testing.T) { testResponseStatus(t, resp, 200) testResponseBody(t, resp, &actual) if actual == nil { - t.Fatalf("") + t.Fatal("expected to get at least one in-flight request, got nil") } -} - -func TestHandler_InFlightRequestWithLoad(t *testing.T) { - core, _, token := vault.TestCoreUnsealed(t) - ln, addr := TestServer(t, core) - defer ln.Close() - TestServerAuth(t, addr, token) - - stop := make(chan string) - - go func() { - i := 0 - for { - select { - case <-stop: - return - default: - break - } - // WRITE - secResp := testHttpPut(t, token, addr+"/v1/secret/foo"+strconv.Itoa(i), map[string]interface{}{ - "data": "bar", - }) - testResponseStatus(t, secResp, 204) - i++ - } - }() - - timeout := time.After(10 * time.Second) - - for { - select { - case <-timeout: - stop <- "done" - t.Fatalf("could not capture any in-flight-req") - return - default: - } - req, err := http.NewRequest("GET", addr+"/v1/sys/in-flight-req", nil) - if err != nil { - t.Fatalf("err: %s", err) - } - req.Header.Set(consts.AuthHeaderName, token) - - client := cleanhttp.DefaultClient() - resp, err := client.Do(req) - if err != nil { - t.Fatalf("err: %s", err) - } - - if resp == nil { - t.Fatalf("nil response") + for _, v := range actual { + reqInfo, ok := v.(map[string]interface{}) + if !ok { + t.Fatal("failed to read in-flight request") } - - var inFlightReqData map[string]interface{} - testResponseStatus(t, resp, 200) - testResponseBody(t, resp, &inFlightReqData) - - if inFlightReqData == nil { - t.Fatalf("") - } - - if inFlightReqData != nil || len(inFlightReqData) > 0 { - stop <- "done" - return + if reqInfo["request_path"] != "/v1/sys/in-flight-req" { + t.Fatalf("expected /v1/sys/in-flight-req in-flight request path, got %s", actual["request_path"]) } } } diff --git a/http/sys_in_flight_requests.go b/http/sys_in_flight_requests.go index 82da072cedf1..cd010b2af846 100644 --- a/http/sys_in_flight_requests.go +++ b/http/sys_in_flight_requests.go @@ -1,8 +1,6 @@ package http import ( - "encoding/json" - "fmt" "net/http" "github.com/hashicorp/vault/vault" @@ -19,15 +17,7 @@ func handleUnAuthenticatedInFlightRequest(core *vault.Core) http.Handler { currentInFlightReqMap := core.LoadInFlightReqData() - content, err := json.Marshal(currentInFlightReqMap) - if err != nil { - respondError(w, http.StatusInternalServerError, fmt.Errorf("error while marshalling the in-flight requests data: %w", err)) - return - } - - w.Header().Set("Content-Type", "application/json") - w.WriteHeader(http.StatusOK) - w.Write(content) + respondOk(w, currentInFlightReqMap) }) } diff --git a/http/sys_in_flight_reqeusts_test.go b/http/sys_in_flight_requests_test.go similarity index 94% rename from http/sys_in_flight_reqeusts_test.go rename to http/sys_in_flight_requests_test.go index 91f8fb3eaf69..de64d708c68f 100644 --- a/http/sys_in_flight_reqeusts_test.go +++ b/http/sys_in_flight_requests_test.go @@ -27,7 +27,7 @@ func TestInFlightRequestUnauthenticated(t *testing.T) { props := &vault.HandlerProperties{ Core: core, ListenerConfig: &configutil.Listener{ - Profiling: configutil.ListenerProfiling{ + InFlightRequestLogging: configutil.ListenerInFlightRequestLogging{ UnauthenticatedInFlightAccess: true, }, }, diff --git a/internalshared/configutil/listener.go b/internalshared/configutil/listener.go index 576033086b01..c4617731e282 100644 --- a/internalshared/configutil/listener.go +++ b/internalshared/configutil/listener.go @@ -27,8 +27,12 @@ type ListenerProfiling struct { UnusedKeys UnusedKeyMap `hcl:",unusedKeyPositions"` UnauthenticatedPProfAccess bool `hcl:"-"` UnauthenticatedPProfAccessRaw interface{} `hcl:"unauthenticated_pprof_access,alias:UnauthenticatedPProfAccessRaw"` +} + +type ListenerInFlightRequestLogging struct { + UnusedKeys UnusedKeyMap `hcl:",unusedKeyPositions"` UnauthenticatedInFlightAccess bool `hcl:"-"` - UnauthenticatedInFlightAccessRaw interface{} `hcl:"unauthenticated_in_flight_request_access,alias:unauthenticatedInFlightAccessRaw"` + UnauthenticatedInFlightAccessRaw interface{} `hcl:"unauthenticated_in_flight_requests_access,alias:unauthenticatedInFlightAccessRaw"` } // Listener is the listener configuration for the server. @@ -89,8 +93,9 @@ type Listener struct { SocketUser string `hcl:"socket_user"` SocketGroup string `hcl:"socket_group"` - Telemetry ListenerTelemetry `hcl:"telemetry"` - Profiling ListenerProfiling `hcl:"profiling"` + Telemetry ListenerTelemetry `hcl:"telemetry"` + Profiling ListenerProfiling `hcl:"profiling"` + InFlightRequestLogging ListenerInFlightRequestLogging `hcl:"inflight_requests_logging"` // RandomPort is used only for some testing purposes RandomPort bool `hcl:"-"` @@ -345,10 +350,16 @@ func ParseListeners(result *SharedConfig, list *ast.ObjectList) error { l.Profiling.UnauthenticatedPProfAccessRaw = nil } - if l.Profiling.UnauthenticatedInFlightAccessRaw != nil { - if l.Profiling.UnauthenticatedInFlightAccess, err = parseutil.ParseBool(l.Profiling.UnauthenticatedInFlightAccessRaw); err != nil { - return multierror.Prefix(fmt.Errorf("invalid value for profiling.unauthenticated_in_flight_request_access: %w", err), fmt.Sprintf("listeners.%d", i)) + } + + // InFlight Request logging + { + if l.InFlightRequestLogging.UnauthenticatedInFlightAccessRaw != nil { + if l.InFlightRequestLogging.UnauthenticatedInFlightAccess, err = parseutil.ParseBool(l.InFlightRequestLogging.UnauthenticatedInFlightAccessRaw); err != nil { + return multierror.Prefix(fmt.Errorf("invalid value for inflight_requests_logging.unauthenticated_in_flight_requests_access: %w", err), fmt.Sprintf("listeners.%d", i)) } + + l.InFlightRequestLogging.UnauthenticatedInFlightAccessRaw = "" } } diff --git a/sdk/logical/request.go b/sdk/logical/request.go index c44b8dd5a82c..d33290e35bde 100644 --- a/sdk/logical/request.go +++ b/sdk/logical/request.go @@ -382,3 +382,9 @@ type CustomHeader struct { Name string Value string } + +type CtxKeyInFlightRequestID struct{} + +func (c CtxKeyInFlightRequestID) String() string { + return "in-flight-request-ID" +} \ No newline at end of file diff --git a/vault/core.go b/vault/core.go index 278eeeefafcf..c4999a9769d3 100644 --- a/vault/core.go +++ b/vault/core.go @@ -1039,7 +1039,7 @@ func NewCore(conf *CoreConfig) (*Core, error) { } switch { - case log.LevelFromString(conf.RawConfig.LogRequestsInfo) > 0: + case log.LevelFromString(conf.RawConfig.LogRequestsInfo) > log.NoLevel && log.LevelFromString(conf.RawConfig.LogRequestsInfo) < log.Off: c.logRequestsInfo = conf.RawConfig.LogRequestsInfo case conf.RawConfig.LogRequestsInfo != "": c.logger.Warn("invalid log_requests_info", "level", conf.RawConfig.LogRequestsInfo) @@ -3023,31 +3023,16 @@ func (c *Core) UpdateInFlightReqData(reqID, clientID string) { c.inFlightReqData.InFlightReqMap.Store(reqID, reqData) } -func (c *Core) logRequests(msg string, args ...interface{}) { - switch c.logRequestsInfo { - case "error": - c.Logger().Error(msg, args...) - case "warn": - c.Logger().Warn(msg, args...) - case "info": - c.Logger().Info(msg, args...) - case "debug": - c.Logger().Debug(msg, args...) - case "trace": - c.Logger().Trace(msg, args...) - } -} - // LogCompletedRequests Logs the completed request to the server logs func (c *Core) LogCompletedRequests(reqID string, statusCode int) { v, ok := c.inFlightReqData.InFlightReqMap.Load(reqID) if !ok { - c.logRequests(fmt.Sprintf("failed to retrieve request with ID %v", reqID)) + c.logger.Log(log.LevelFromString(c.logRequestsInfo), fmt.Sprintf("failed to retrieve request with ID %v", reqID)) return } // there is only one writer to this map, so skip checking for errors reqData, _ := v.(*InFlightReqData) - c.logRequests("completed_request","client_id", reqData.ClientID, "client_address", reqData.ClientRemoteAddr, "status_code", statusCode, "request_path", reqData.ReqPath, "request_method", reqData.Method) + c.logger.Log(log.LevelFromString(c.logRequestsInfo), "completed_request","client_id", reqData.ClientID, "client_address", reqData.ClientRemoteAddr, "status_code", statusCode, "request_path", reqData.ReqPath, "request_method", reqData.Method) } func (c *Core) ReloadLogRequestsInfo(){ @@ -3057,7 +3042,7 @@ func (c *Core) ReloadLogRequestsInfo(){ } infoLevel := conf.(*server.Config).LogRequestsInfo switch { - case log.LevelFromString(infoLevel) > 0: + case log.LevelFromString(infoLevel) > log.NoLevel && log.LevelFromString(infoLevel) < log.Off: c.logRequestsInfo = infoLevel case infoLevel != "": c.logger.Warn("invalid log_requests_info", "level", infoLevel) diff --git a/vault/request_handling.go b/vault/request_handling.go index 7447846b8d51..8fb6d067c1ce 100644 --- a/vault/request_handling.go +++ b/vault/request_handling.go @@ -440,9 +440,9 @@ func (c *Core) switchedLockHandleRequest(httpCtx context.Context, req *logical.R } ctx = namespace.ContextWithNamespace(ctx, ns) - inFlightReqID, ok := httpCtx.Value("in-flight-reqID").(string) + inFlightReqID, ok := httpCtx.Value(logical.CtxKeyInFlightRequestID{}).(string) if ok { - ctx = context.WithValue(ctx, "in-flight-reqID", inFlightReqID) + ctx = context.WithValue(ctx, logical.CtxKeyInFlightRequestID{}, inFlightReqID) } resp, err = c.handleCancelableRequest(ctx, req) @@ -778,14 +778,9 @@ func (c *Core) handleRequest(ctx context.Context, req *logical.Request) (retResp } // Updating in-flight request data with client/entity ID - inFlightReqID, ok := ctx.Value("in-flight-reqID").(string) - if ok { - switch { - case req.ClientID != "": - c.UpdateInFlightReqData(inFlightReqID, req.ClientID) - case req.EntityID != "": - c.UpdateInFlightReqData(inFlightReqID, req.EntityID) - } + inFlightReqID, ok := ctx.Value(logical.CtxKeyInFlightRequestID{}).(string) + if ok && req.ClientID != "" { + c.UpdateInFlightReqData(inFlightReqID, req.ClientID) } // We run this logic first because we want to decrement the use count even @@ -1181,6 +1176,13 @@ func (c *Core) handleLoginRequest(ctx context.Context, req *logical.Request) (re if ctErr == logical.ErrPerfStandbyPleaseForward { return nil, nil, ctErr } + + // Updating in-flight request data with client/entity ID + inFlightReqID, ok := ctx.Value(logical.CtxKeyInFlightRequestID{}).(string) + if ok && req.ClientID != "" { + c.UpdateInFlightReqData(inFlightReqID, req.ClientID) + } + if ctErr != nil { // If it is an internal error we return that, otherwise we // return invalid request so that the status codes can be correct diff --git a/website/content/docs/internals/telemetry.mdx b/website/content/docs/internals/telemetry.mdx index 5b3ad27b6316..a0061af62c35 100644 --- a/website/content/docs/internals/telemetry.mdx +++ b/website/content/docs/internals/telemetry.mdx @@ -91,7 +91,7 @@ These metrics represent operational aspects of the running Vault instance. | `vault.core.fetch_acl_and_token` | Duration of time taken by ACL and corresponding token entry fetches handled by Vault core | ms | summary | | `vault.core.handle_request` | Duration of time taken by requests handled by Vault core | ms | summary | | `vault.core.handle_login_request` | Duration of time taken by login requests handled by Vault core | ms | summary | -| `vault.core.in_flight_request` | Number of in-flight requests. | requests | gauge | +| `vault.core.in_flight_requests` | Number of in-flight requests. | requests | gauge | | `vault.core.leadership_setup_failed` | Duration of time taken by cluster leadership setup failures which have occurred in a highly available Vault cluster. This should be monitored and alerted on for overall cluster leadership status. | ms | summary | | `vault.core.leadership_lost` | Duration of time taken by cluster leadership losses which have occurred in a highly available Vault cluster. This should be monitored and alerted on for overall cluster leadership status. | ms | summary | | `vault.core.license.expiration_time_epoch` | Time as epoch (seconds since Jan 1 1970) at which license will expire. | seconds | gauge | From 6ecb241e04ded05694a55e6059c63a97ce3d4a85 Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Wed, 24 Nov 2021 16:53:26 -0800 Subject: [PATCH 17/33] Fixing a test --- command/server/listener_test.go | 4 ++-- ...nauth_in_flight_access.hcl => unauth_in_flight_access.hcl} | 4 ++-- 2 files changed, 4 insertions(+), 4 deletions(-) rename command/server/test-fixtures/{profiling_unauth_in_flight_access.hcl => unauth_in_flight_access.hcl} (57%) diff --git a/command/server/listener_test.go b/command/server/listener_test.go index c4d962d8bdf9..cda5b733e26b 100644 --- a/command/server/listener_test.go +++ b/command/server/listener_test.go @@ -71,11 +71,11 @@ func testListenerImpl(t *testing.T, ln net.Listener, connFn testListenerConnFn, func TestProfilingUnauthenticatedInFlightAccess(t *testing.T) { - config, err := LoadConfigFile("./test-fixtures/profiling_unauth_in_flight_access.hcl") + config, err := LoadConfigFile("./test-fixtures/unauth_in_flight_access.hcl") if err != nil { t.Fatalf("Error encountered when loading config %+v", err) } - if !config.Listeners[0].Profiling.UnauthenticatedInFlightAccess { + if !config.Listeners[0].InFlightRequestLogging.UnauthenticatedInFlightAccess { t.Fatalf("failed to read UnauthenticatedInFlightAccess") } } \ No newline at end of file diff --git a/command/server/test-fixtures/profiling_unauth_in_flight_access.hcl b/command/server/test-fixtures/unauth_in_flight_access.hcl similarity index 57% rename from command/server/test-fixtures/profiling_unauth_in_flight_access.hcl rename to command/server/test-fixtures/unauth_in_flight_access.hcl index d865fb8b05af..eda6641276f1 100644 --- a/command/server/test-fixtures/profiling_unauth_in_flight_access.hcl +++ b/command/server/test-fixtures/unauth_in_flight_access.hcl @@ -2,8 +2,8 @@ storage "inmem" {} listener "tcp" { address = "127.0.0.1:8200" tls_disable = true - profiling { - unauthenticated_in_flight_request_access = true + inflight_requests_logging { + unauthenticated_in_flight_requests_access = true } } disable_mlock = true From ec225172c240b3588767426e601c76823c3d1a97 Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Thu, 25 Nov 2021 09:53:52 -0800 Subject: [PATCH 18/33] use an tomic value for logRequestsInfo, and moving the CreateClientID function to Core --- go.sum | 2 - http/handler.go | 2 +- http/handler_test.go | 4 +- vault/activity_log.go | 10 ++--- vault/activity_log_test.go | 91 ++++++++------------------------------ vault/core.go | 13 +++--- vault/core_metrics.go | 2 +- vault/core_test.go | 61 +++++++++++++++++++++++++ vault/request_handling.go | 54 +++++++++++++++++++++- 9 files changed, 148 insertions(+), 91 deletions(-) diff --git a/go.sum b/go.sum index 6a7e2573143a..0c7a7d98824d 100644 --- a/go.sum +++ b/go.sum @@ -968,8 +968,6 @@ github.com/hashicorp/vault-plugin-secrets-gcpkms v0.10.0 h1:0Vi5WEIpZctk/ZoRClod github.com/hashicorp/vault-plugin-secrets-gcpkms v0.10.0/go.mod h1:6DPwGu8oGR1sZRpjwkcAnrQZWQuAJ/Ph+rQHfUo1Yf4= github.com/hashicorp/vault-plugin-secrets-kv v0.5.7-0.20211123171606-16933c88368a h1:GVA3sY+FRhQrMexWGMCsIfVVMgcdru36WMKvDtKed5I= github.com/hashicorp/vault-plugin-secrets-kv v0.5.7-0.20211123171606-16933c88368a/go.mod h1:TNPRoB53Twd9tYvlhqqEhMsQPiVN604kZw9jr2zUzDk= -github.com/hashicorp/vault-plugin-secrets-kv v0.10.1 h1:88a6YkbU0FCboZoFdB5uv6ukBf3gc3zDLKM4z64dWxo= -github.com/hashicorp/vault-plugin-secrets-kv v0.10.1/go.mod h1:TNPRoB53Twd9tYvlhqqEhMsQPiVN604kZw9jr2zUzDk= github.com/hashicorp/vault-plugin-secrets-mongodbatlas v0.5.1 h1:Maewon4nu0KL1ALBOvL6Rsj+Qyr9hdULWflyMz7+9nk= github.com/hashicorp/vault-plugin-secrets-mongodbatlas v0.5.1/go.mod h1:PLx2vxXukfsKsDRo/PlG4fxmJ1d+H2h82wT3vf4buuI= github.com/hashicorp/vault-plugin-secrets-openldap v0.6.0 h1:d6N/aMlklMfEacyiIuu5ZnTlADhGkGZkDrOtQXBRuhI= diff --git a/http/handler.go b/http/handler.go index 9bea2fb542b0..6f95830d330f 100644 --- a/http/handler.go +++ b/http/handler.go @@ -392,7 +392,7 @@ func wrapGenericHandler(core *vault.Core, h http.Handler, props *vault.HandlerPr headers := r.Header[textproto.CanonicalMIMEHeaderKey("X-Forwarded-For")] if len(headers) == 0 { clientAddr = r.RemoteAddr - }else { + } else { clientAddr = headers[0] } diff --git a/http/handler_test.go b/http/handler_test.go index 999a776c7489..b6f448c86a20 100644 --- a/http/handler_test.go +++ b/http/handler_test.go @@ -319,8 +319,8 @@ func TestHandler_InFlightRequest(t *testing.T) { var actual map[string]interface{} testResponseStatus(t, resp, 200) testResponseBody(t, resp, &actual) - if actual == nil { - t.Fatal("expected to get at least one in-flight request, got nil") + if actual == nil || len(actual) == 0 { + t.Fatal("expected to get at least one in-flight request, got nil or zero length map") } for _, v := range actual { reqInfo, ok := v.(map[string]interface{}) diff --git a/vault/activity_log.go b/vault/activity_log.go index d6d6ad9fbcf6..c279ff3ed018 100644 --- a/vault/activity_log.go +++ b/vault/activity_log.go @@ -1593,30 +1593,28 @@ func (a *ActivityLog) loadConfigOrDefault(ctx context.Context) (activityConfig, // HandleTokenUsage adds the TokenEntry to the current fragment of the activity log // and returns the corresponding Client ID. // This currently occurs on token usage only. -func (a *ActivityLog) HandleTokenUsage(entry *logical.TokenEntry) string { +func (a *ActivityLog) HandleTokenUsage(entry *logical.TokenEntry, clientID string, isTWE bool) { // First, check if a is enabled, so as to avoid the cost of creating an ID for // tokens without entities in the case where it not. a.fragmentLock.RLock() if !a.enabled { a.fragmentLock.RUnlock() - return "" + return } a.fragmentLock.RUnlock() // Do not count wrapping tokens in client count if IsWrappingToken(entry) { - return "" + return } // Do not count root tokens in client count. if entry.IsRoot() { - return "" + return } // Parse an entry's client ID and add it to the activity log - clientID, isTWE := a.CreateClientID(entry) a.AddClientToFragment(clientID, entry.NamespaceID, entry.CreationTime, isTWE) - return clientID } // CreateClientID returns the client ID, and a boolean which is false if the clientID diff --git a/vault/activity_log_test.go b/vault/activity_log_test.go index 12c95bbc67ae..743a9ea601ca 100644 --- a/vault/activity_log_test.go +++ b/vault/activity_log_test.go @@ -2,8 +2,6 @@ package vault import ( "context" - "crypto/sha256" - "encoding/base64" "encoding/json" "errors" "fmt" @@ -114,13 +112,16 @@ func TestActivityLog_Creation_WrappingTokens(t *testing.T) { a.fragmentLock.Unlock() const namespace_id = "ns123" - a.HandleTokenUsage(&logical.TokenEntry{ + te := &logical.TokenEntry{ Path: "test", Policies: []string{responseWrappingPolicyName}, CreationTime: time.Now().Unix(), TTL: 3600, NamespaceID: namespace_id, - }) + } + + id, isTWE := core.CreateClientID(te) + a.HandleTokenUsage(te, id, isTWE) a.fragmentLock.Lock() if a.fragment != nil { @@ -128,13 +129,16 @@ func TestActivityLog_Creation_WrappingTokens(t *testing.T) { } a.fragmentLock.Unlock() - a.HandleTokenUsage(&logical.TokenEntry{ + teNew := &logical.TokenEntry{ Path: "test", Policies: []string{controlGroupPolicyName}, CreationTime: time.Now().Unix(), TTL: 3600, NamespaceID: namespace_id, - }) + } + + id, isTWE = core.CreateClientID(teNew) + a.HandleTokenUsage(teNew, id, isTWE) a.fragmentLock.Lock() if a.fragment != nil { @@ -359,13 +363,15 @@ func TestActivityLog_SaveTokensToStorageDoesNotUpdateTokenCount(t *testing.T) { tokenEntryOne := logical.TokenEntry{NamespaceID: "ns1_id", Policies: []string{"hi"}} entityEntry := logical.TokenEntry{EntityID: "foo", NamespaceID: "ns1_id", Policies: []string{"hi"}} - id, _ := a.CreateClientID(&tokenEntryOne) + idNonEntity, isTWE := core.CreateClientID(&tokenEntryOne) for i := 0; i < 3; i++ { - a.HandleTokenUsage(&tokenEntryOne) + a.HandleTokenUsage(&tokenEntryOne, idNonEntity, isTWE) } + + idEntity, isTWE := core.CreateClientID(&entityEntry) for i := 0; i < 2; i++ { - a.HandleTokenUsage(&entityEntry) + a.HandleTokenUsage(&entityEntry, idEntity, isTWE) } err := a.saveCurrentSegmentToStorage(ctx, false) if err != nil { @@ -394,14 +400,14 @@ func TestActivityLog_SaveTokensToStorageDoesNotUpdateTokenCount(t *testing.T) { for _, client := range out.Clients { if client.NonEntity == true { nonEntityTokenFlag = true - if client.ClientID != id { - t.Fatalf("expected a client ID of %s, but saved instead %s", id, client.ClientID) + if client.ClientID != idNonEntity { + t.Fatalf("expected a client ID of %s, but saved instead %s", idNonEntity, client.ClientID) } } if client.NonEntity == false { entityTokenFlag = true - if client.ClientID != "foo" { - t.Fatalf("expected a client ID of %s, but saved instead %s", "foo", client.ClientID) + if client.ClientID != idEntity { + t.Fatalf("expected a client ID of %s, but saved instead %s", idEntity, client.ClientID) } } } @@ -1520,65 +1526,6 @@ func TestActivityLog_refreshFromStoredLog(t *testing.T) { } } -// TestCreateClientID verifies that CreateClientID uses the entity ID for a token -// entry if one exists, and creates an appropriate client ID otherwise. -func TestCreateClientID(t *testing.T) { - entry := logical.TokenEntry{NamespaceID: "namespaceFoo", Policies: []string{"bar", "baz", "foo", "banana"}} - activityLog := ActivityLog{} - id, isTWE := activityLog.CreateClientID(&entry) - if !isTWE { - t.Fatalf("TWE token should return true value in isTWE bool") - } - expectedIDPlaintext := "banana" + string(sortedPoliciesTWEDelimiter) + "bar" + - string(sortedPoliciesTWEDelimiter) + "baz" + - string(sortedPoliciesTWEDelimiter) + "foo" + string(clientIDTWEDelimiter) + "namespaceFoo" - - hashed := sha256.Sum256([]byte(expectedIDPlaintext)) - expectedID := base64.StdEncoding.EncodeToString(hashed[:]) - if expectedID != id { - t.Fatalf("wrong ID: expected %s, found %s", expectedID, id) - } - // Test with entityID - entry = logical.TokenEntry{EntityID: "entityFoo", NamespaceID: "namespaceFoo", Policies: []string{"bar", "baz", "foo", "banana"}} - id, isTWE = activityLog.CreateClientID(&entry) - if isTWE { - t.Fatalf("token with entity should return false value in isTWE bool") - } - if id != "entityFoo" { - t.Fatalf("client ID should be entity ID") - } - - // Test without namespace - entry = logical.TokenEntry{Policies: []string{"bar", "baz", "foo", "banana"}} - id, isTWE = activityLog.CreateClientID(&entry) - if !isTWE { - t.Fatalf("TWE token should return true value in isTWE bool") - } - expectedIDPlaintext = "banana" + string(sortedPoliciesTWEDelimiter) + "bar" + - string(sortedPoliciesTWEDelimiter) + "baz" + - string(sortedPoliciesTWEDelimiter) + "foo" + string(clientIDTWEDelimiter) - - hashed = sha256.Sum256([]byte(expectedIDPlaintext)) - expectedID = base64.StdEncoding.EncodeToString(hashed[:]) - if expectedID != id { - t.Fatalf("wrong ID: expected %s, found %s", expectedID, id) - } - - // Test without policies - entry = logical.TokenEntry{NamespaceID: "namespaceFoo"} - id, isTWE = activityLog.CreateClientID(&entry) - if !isTWE { - t.Fatalf("TWE token should return true value in isTWE bool") - } - expectedIDPlaintext = "namespaceFoo" - - hashed = sha256.Sum256([]byte(expectedIDPlaintext)) - expectedID = base64.StdEncoding.EncodeToString(hashed[:]) - if expectedID != id { - t.Fatalf("wrong ID: expected %s, found %s", expectedID, id) - } -} - func TestActivityLog_refreshFromStoredLogWithBackgroundLoadingCancelled(t *testing.T) { a, expectedClientRecords, expectedTokenCounts := setupActivityRecordsInStorage(t, time.Now().UTC(), true, true) a.SetEnable(true) diff --git a/vault/core.go b/vault/core.go index c4999a9769d3..0255fed470c0 100644 --- a/vault/core.go +++ b/vault/core.go @@ -390,7 +390,7 @@ type Core struct { physicalCache physical.ToggleablePurgemonster // logRequestsInfo indicates at which level requests should be logged - logRequestsInfo string + logRequestsInfo uberAtomic.String // reloadFuncs is a map containing reload functions reloadFuncs map[string][]reloadutil.ReloadFunc @@ -1040,7 +1040,7 @@ func NewCore(conf *CoreConfig) (*Core, error) { switch { case log.LevelFromString(conf.RawConfig.LogRequestsInfo) > log.NoLevel && log.LevelFromString(conf.RawConfig.LogRequestsInfo) < log.Off: - c.logRequestsInfo = conf.RawConfig.LogRequestsInfo + c.logRequestsInfo.Store(conf.RawConfig.LogRequestsInfo) case conf.RawConfig.LogRequestsInfo != "": c.logger.Warn("invalid log_requests_info", "level", conf.RawConfig.LogRequestsInfo) } @@ -2988,7 +2988,7 @@ func (c *Core) StoreInFlightReqData(reqID string, data *InFlightReqData) { // request from the inFlightReqMap and decrement the number of in-flight // requests by one. func (c *Core) FinalizeInFlightReqData(reqID string, statusCode int) { - if c.logRequestsInfo != "" { + if c.logRequestsInfo.Load() != "" { c.LogCompletedRequests(reqID, statusCode) } c.inFlightReqData.InFlightReqMap.Delete(reqID) @@ -3026,13 +3026,14 @@ func (c *Core) UpdateInFlightReqData(reqID, clientID string) { // LogCompletedRequests Logs the completed request to the server logs func (c *Core) LogCompletedRequests(reqID string, statusCode int) { v, ok := c.inFlightReqData.InFlightReqMap.Load(reqID) + logInfoLevel := log.LevelFromString(c.logRequestsInfo.Load()) if !ok { - c.logger.Log(log.LevelFromString(c.logRequestsInfo), fmt.Sprintf("failed to retrieve request with ID %v", reqID)) + c.logger.Log(logInfoLevel, fmt.Sprintf("failed to retrieve request with ID %v", reqID)) return } // there is only one writer to this map, so skip checking for errors reqData, _ := v.(*InFlightReqData) - c.logger.Log(log.LevelFromString(c.logRequestsInfo), "completed_request","client_id", reqData.ClientID, "client_address", reqData.ClientRemoteAddr, "status_code", statusCode, "request_path", reqData.ReqPath, "request_method", reqData.Method) + c.logger.Log(logInfoLevel, "completed_request","client_id", reqData.ClientID, "client_address", reqData.ClientRemoteAddr, "status_code", statusCode, "request_path", reqData.ReqPath, "request_method", reqData.Method) } func (c *Core) ReloadLogRequestsInfo(){ @@ -3043,7 +3044,7 @@ func (c *Core) ReloadLogRequestsInfo(){ infoLevel := conf.(*server.Config).LogRequestsInfo switch { case log.LevelFromString(infoLevel) > log.NoLevel && log.LevelFromString(infoLevel) < log.Off: - c.logRequestsInfo = infoLevel + c.logRequestsInfo.Store(infoLevel) case infoLevel != "": c.logger.Warn("invalid log_requests_info", "level", infoLevel) } diff --git a/vault/core_metrics.go b/vault/core_metrics.go index a95770f328aa..acf021a52009 100644 --- a/vault/core_metrics.go +++ b/vault/core_metrics.go @@ -541,5 +541,5 @@ func (c *Core) cachedGaugeMetricsEmitter() { func (c *Core) inFlightReqGaugeMetric() { totalInFlightReq := c.inFlightReqData.InFlightReqCount.Load() // Adding a gauge metric to capture total number of inflight requests - c.metricSink.SetGaugeWithLabels([]string{"core", "in_flight_request"}, float32(totalInFlightReq), nil) + c.metricSink.SetGaugeWithLabels([]string{"core", "in_flight_requests"}, float32(totalInFlightReq), nil) } diff --git a/vault/core_test.go b/vault/core_test.go index 157d6db1e38c..d849c748bc02 100644 --- a/vault/core_test.go +++ b/vault/core_test.go @@ -2,6 +2,8 @@ package vault import ( "context" + "crypto/sha256" + "encoding/base64" "fmt" "reflect" "sync" @@ -2594,3 +2596,62 @@ func TestCore_ServiceRegistration(t *testing.T) { t.Fatal(diff) } } + +// TestCreateClientID verifies that CreateClientID uses the entity ID for a token +// entry if one exists, and creates an appropriate client ID otherwise. +func TestCreateClientID(t *testing.T) { + entry := logical.TokenEntry{NamespaceID: "namespaceFoo", Policies: []string{"bar", "baz", "foo", "banana"}} + core := Core{} + id, isTWE := core.CreateClientID(&entry) + if !isTWE { + t.Fatalf("TWE token should return true value in isTWE bool") + } + expectedIDPlaintext := "banana" + string(sortedPoliciesTWEDelimiter) + "bar" + + string(sortedPoliciesTWEDelimiter) + "baz" + + string(sortedPoliciesTWEDelimiter) + "foo" + string(clientIDTWEDelimiter) + "namespaceFoo" + + hashed := sha256.Sum256([]byte(expectedIDPlaintext)) + expectedID := base64.StdEncoding.EncodeToString(hashed[:]) + if expectedID != id { + t.Fatalf("wrong ID: expected %s, found %s", expectedID, id) + } + // Test with entityID + entry = logical.TokenEntry{EntityID: "entityFoo", NamespaceID: "namespaceFoo", Policies: []string{"bar", "baz", "foo", "banana"}} + id, isTWE = core.CreateClientID(&entry) + if isTWE { + t.Fatalf("token with entity should return false value in isTWE bool") + } + if id != "entityFoo" { + t.Fatalf("client ID should be entity ID") + } + + // Test without namespace + entry = logical.TokenEntry{Policies: []string{"bar", "baz", "foo", "banana"}} + id, isTWE = core.CreateClientID(&entry) + if !isTWE { + t.Fatalf("TWE token should return true value in isTWE bool") + } + expectedIDPlaintext = "banana" + string(sortedPoliciesTWEDelimiter) + "bar" + + string(sortedPoliciesTWEDelimiter) + "baz" + + string(sortedPoliciesTWEDelimiter) + "foo" + string(clientIDTWEDelimiter) + + hashed = sha256.Sum256([]byte(expectedIDPlaintext)) + expectedID = base64.StdEncoding.EncodeToString(hashed[:]) + if expectedID != id { + t.Fatalf("wrong ID: expected %s, found %s", expectedID, id) + } + + // Test without policies + entry = logical.TokenEntry{NamespaceID: "namespaceFoo"} + id, isTWE = core.CreateClientID(&entry) + if !isTWE { + t.Fatalf("TWE token should return true value in isTWE bool") + } + expectedIDPlaintext = "namespaceFoo" + + hashed = sha256.Sum256([]byte(expectedIDPlaintext)) + expectedID = base64.StdEncoding.EncodeToString(hashed[:]) + if expectedID != id { + t.Fatalf("wrong ID: expected %s, found %s", expectedID, id) + } +} diff --git a/vault/request_handling.go b/vault/request_handling.go index 8fb6d067c1ce..c2c8f4e4ffe0 100644 --- a/vault/request_handling.go +++ b/vault/request_handling.go @@ -2,8 +2,11 @@ package vault import ( "context" + "crypto/sha256" + "encoding/base64" "errors" "fmt" + "sort" "strings" "time" @@ -396,13 +399,62 @@ func (c *Core) checkToken(ctx context.Context, req *logical.Request, unauth bool return auth, te, retErr } + var clientID string + var isTWE bool + if te != nil { + clientID, isTWE = c.CreateClientID(te) + req.ClientID = clientID + } + // If it is an authenticated ( i.e with vault token ) request, increment client count if !unauth && c.activityLog != nil { - req.ClientID = c.activityLog.HandleTokenUsage(te) + c.activityLog.HandleTokenUsage(te, clientID, isTWE) } return auth, te, nil } +// CreateClientID returns the client ID, and a boolean which is false if the clientID +// has an entity, and true otherwise +func (c *Core) CreateClientID(entry *logical.TokenEntry) (string, bool) { + var clientIDInputBuilder strings.Builder + + // if entry has an associated entity ID, return it + if entry.EntityID != "" { + return entry.EntityID, false + } + + // The entry is associated with a TWE (token without entity). In this case + // we must create a client ID by calculating the following formula: + // clientID = SHA256(sorted policies + namespace) + + // Step 1: Copy entry policies to a new struct + sortedPolicies := make([]string, len(entry.Policies)) + copy(sortedPolicies, entry.Policies) + + // Step 2: Sort and join copied policies + sort.Strings(sortedPolicies) + for _, pol := range sortedPolicies { + clientIDInputBuilder.WriteRune(sortedPoliciesTWEDelimiter) + clientIDInputBuilder.WriteString(pol) + } + + // Step 3: Add namespace ID + clientIDInputBuilder.WriteRune(clientIDTWEDelimiter) + clientIDInputBuilder.WriteString(entry.NamespaceID) + + if clientIDInputBuilder.Len() == 0 { + c.logger.Error("vault token with no entity ID, policies, or namespace was recorded " + + "in the activity log") + return "", true + } + // Step 4: Remove the first character in the string, as it's an unnecessary delimiter + clientIDInput := clientIDInputBuilder.String()[1:] + + // Step 5: Hash the sum + hashed := sha256.Sum256([]byte(clientIDInput)) + return base64.StdEncoding.EncodeToString(hashed[:]), true +} + // HandleRequest is used to handle a new incoming request func (c *Core) HandleRequest(httpCtx context.Context, req *logical.Request) (resp *logical.Response, err error) { return c.switchedLockHandleRequest(httpCtx, req, true) From 8a6350e37096f73fcf550800b399c414a9b8ef05 Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Thu, 25 Nov 2021 09:57:46 -0800 Subject: [PATCH 19/33] fixing go.sum --- go.sum | 2 ++ 1 file changed, 2 insertions(+) diff --git a/go.sum b/go.sum index 0c7a7d98824d..6a7e2573143a 100644 --- a/go.sum +++ b/go.sum @@ -968,6 +968,8 @@ github.com/hashicorp/vault-plugin-secrets-gcpkms v0.10.0 h1:0Vi5WEIpZctk/ZoRClod github.com/hashicorp/vault-plugin-secrets-gcpkms v0.10.0/go.mod h1:6DPwGu8oGR1sZRpjwkcAnrQZWQuAJ/Ph+rQHfUo1Yf4= github.com/hashicorp/vault-plugin-secrets-kv v0.5.7-0.20211123171606-16933c88368a h1:GVA3sY+FRhQrMexWGMCsIfVVMgcdru36WMKvDtKed5I= github.com/hashicorp/vault-plugin-secrets-kv v0.5.7-0.20211123171606-16933c88368a/go.mod h1:TNPRoB53Twd9tYvlhqqEhMsQPiVN604kZw9jr2zUzDk= +github.com/hashicorp/vault-plugin-secrets-kv v0.10.1 h1:88a6YkbU0FCboZoFdB5uv6ukBf3gc3zDLKM4z64dWxo= +github.com/hashicorp/vault-plugin-secrets-kv v0.10.1/go.mod h1:TNPRoB53Twd9tYvlhqqEhMsQPiVN604kZw9jr2zUzDk= github.com/hashicorp/vault-plugin-secrets-mongodbatlas v0.5.1 h1:Maewon4nu0KL1ALBOvL6Rsj+Qyr9hdULWflyMz7+9nk= github.com/hashicorp/vault-plugin-secrets-mongodbatlas v0.5.1/go.mod h1:PLx2vxXukfsKsDRo/PlG4fxmJ1d+H2h82wT3vf4buuI= github.com/hashicorp/vault-plugin-secrets-openldap v0.6.0 h1:d6N/aMlklMfEacyiIuu5ZnTlADhGkGZkDrOtQXBRuhI= From b9dad8c0be90c09fbebc56a06d546081cefd4cf8 Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Thu, 25 Nov 2021 10:06:12 -0800 Subject: [PATCH 20/33] minor refactoring --- vault/core.go | 6 +++--- vault/request_handling.go | 11 ++++------- 2 files changed, 7 insertions(+), 10 deletions(-) diff --git a/vault/core.go b/vault/core.go index 0255fed470c0..40d5aa479395 100644 --- a/vault/core.go +++ b/vault/core.go @@ -3026,14 +3026,14 @@ func (c *Core) UpdateInFlightReqData(reqID, clientID string) { // LogCompletedRequests Logs the completed request to the server logs func (c *Core) LogCompletedRequests(reqID string, statusCode int) { v, ok := c.inFlightReqData.InFlightReqMap.Load(reqID) - logInfoLevel := log.LevelFromString(c.logRequestsInfo.Load()) + logLevel := log.LevelFromString(c.logRequestsInfo.Load()) if !ok { - c.logger.Log(logInfoLevel, fmt.Sprintf("failed to retrieve request with ID %v", reqID)) + c.logger.Log(logLevel, fmt.Sprintf("failed to retrieve request with ID %v", reqID)) return } // there is only one writer to this map, so skip checking for errors reqData, _ := v.(*InFlightReqData) - c.logger.Log(logInfoLevel, "completed_request","client_id", reqData.ClientID, "client_address", reqData.ClientRemoteAddr, "status_code", statusCode, "request_path", reqData.ReqPath, "request_method", reqData.Method) + c.logger.Log(logLevel, "completed_request","client_id", reqData.ClientID, "client_address", reqData.ClientRemoteAddr, "status_code", statusCode, "request_path", reqData.ReqPath, "request_method", reqData.Method) } func (c *Core) ReloadLogRequestsInfo(){ diff --git a/vault/request_handling.go b/vault/request_handling.go index c2c8f4e4ffe0..e7f82aac916f 100644 --- a/vault/request_handling.go +++ b/vault/request_handling.go @@ -349,6 +349,8 @@ func (c *Core) checkToken(ctx context.Context, req *logical.Request, unauth bool Accessor: req.ClientTokenAccessor, } + var clientID string + var isTWE bool if te != nil { auth.IdentityPolicies = identityPolicies[te.NamespaceID] auth.TokenPolicies = te.Policies @@ -365,6 +367,8 @@ func (c *Core) checkToken(ctx context.Context, req *logical.Request, unauth bool if te.CreationTime > 0 { auth.IssueTime = time.Unix(te.CreationTime, 0) } + clientID, isTWE = c.CreateClientID(te) + req.ClientID = clientID } // Check the standard non-root ACLs. Return the token entry if it's not @@ -399,13 +403,6 @@ func (c *Core) checkToken(ctx context.Context, req *logical.Request, unauth bool return auth, te, retErr } - var clientID string - var isTWE bool - if te != nil { - clientID, isTWE = c.CreateClientID(te) - req.ClientID = clientID - } - // If it is an authenticated ( i.e with vault token ) request, increment client count if !unauth && c.activityLog != nil { c.activityLog.HandleTokenUsage(te, clientID, isTWE) From e3079f0ad31352b7b5ea199e3d4a84508b7bc809 Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Thu, 25 Nov 2021 12:05:51 -0800 Subject: [PATCH 21/33] protecting InFlightRequests from data race --- vault/core.go | 20 +++++++++++++++++++- 1 file changed, 19 insertions(+), 1 deletion(-) diff --git a/vault/core.go b/vault/core.go index 40d5aa479395..2f9e516a8450 100644 --- a/vault/core.go +++ b/vault/core.go @@ -2966,6 +2966,7 @@ type LicenseState struct { } type InFlightRequests struct { + l sync.RWMutex InFlightReqMap *sync.Map InFlightReqCount *uberAtomic.Uint64 } @@ -2979,6 +2980,8 @@ type InFlightReqData struct { } func (c *Core) StoreInFlightReqData(reqID string, data *InFlightReqData) { + c.inFlightReqData.l.Lock() + defer c.inFlightReqData.l.Unlock() c.inFlightReqData.InFlightReqMap.Store(reqID, data) c.inFlightReqData.InFlightReqCount.Inc() } @@ -2991,6 +2994,9 @@ func (c *Core) FinalizeInFlightReqData(reqID string, statusCode int) { if c.logRequestsInfo.Load() != "" { c.LogCompletedRequests(reqID, statusCode) } + + c.inFlightReqData.l.Lock() + defer c.inFlightReqData.l.Unlock() c.inFlightReqData.InFlightReqMap.Delete(reqID) c.inFlightReqData.InFlightReqCount.Dec() } @@ -2999,6 +3005,8 @@ func (c *Core) FinalizeInFlightReqData(reqID string, statusCode int) { // in-flight requests func (c *Core) LoadInFlightReqData() map[string]*InFlightReqData { currentInFlightReqMap := make(map[string]*InFlightReqData) + c.inFlightReqData.l.RLock() + defer c.inFlightReqData.l.RUnlock() c.inFlightReqData.InFlightReqMap.Range(func(key, value interface{}) bool { // there is only one writer to this map, so skip checking for errors v, _ := value.(*InFlightReqData) @@ -3013,24 +3021,34 @@ func (c *Core) LoadInFlightReqData() map[string]*InFlightReqData { // UpdateInFlightReqData updates the data for a specific reqID with // the clientID func (c *Core) UpdateInFlightReqData(reqID, clientID string) { + c.inFlightReqData.l.RLock() v, ok := c.inFlightReqData.InFlightReqMap.Load(reqID) if !ok { + defer c.inFlightReqData.l.RUnlock() c.Logger().Trace("failed to retrieve request with ID %v", reqID) return } + c.inFlightReqData.l.RUnlock() + reqData, _ := v.(*InFlightReqData) reqData.ClientID = clientID + c.inFlightReqData.l.Lock() + defer c.inFlightReqData.l.Unlock() c.inFlightReqData.InFlightReqMap.Store(reqID, reqData) } // LogCompletedRequests Logs the completed request to the server logs func (c *Core) LogCompletedRequests(reqID string, statusCode int) { - v, ok := c.inFlightReqData.InFlightReqMap.Load(reqID) logLevel := log.LevelFromString(c.logRequestsInfo.Load()) + c.inFlightReqData.l.RLock() + v, ok := c.inFlightReqData.InFlightReqMap.Load(reqID) if !ok { + defer c.inFlightReqData.l.RUnlock() c.logger.Log(logLevel, fmt.Sprintf("failed to retrieve request with ID %v", reqID)) return } + c.inFlightReqData.l.RUnlock() + // there is only one writer to this map, so skip checking for errors reqData, _ := v.(*InFlightReqData) c.logger.Log(logLevel, "completed_request","client_id", reqData.ClientID, "client_address", reqData.ClientRemoteAddr, "status_code", statusCode, "request_path", reqData.ReqPath, "request_method", reqData.Method) From 96e5c7185b7c42cec79614093d573f913cc80805 Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Thu, 25 Nov 2021 12:37:39 -0800 Subject: [PATCH 22/33] another try on fixing a data race --- vault/core.go | 16 ++++++---------- 1 file changed, 6 insertions(+), 10 deletions(-) diff --git a/vault/core.go b/vault/core.go index 2f9e516a8450..88102ea1854e 100644 --- a/vault/core.go +++ b/vault/core.go @@ -3005,8 +3005,8 @@ func (c *Core) FinalizeInFlightReqData(reqID string, statusCode int) { // in-flight requests func (c *Core) LoadInFlightReqData() map[string]*InFlightReqData { currentInFlightReqMap := make(map[string]*InFlightReqData) - c.inFlightReqData.l.RLock() - defer c.inFlightReqData.l.RUnlock() + c.inFlightReqData.l.Lock() + defer c.inFlightReqData.l.Unlock() c.inFlightReqData.InFlightReqMap.Range(func(key, value interface{}) bool { // there is only one writer to this map, so skip checking for errors v, _ := value.(*InFlightReqData) @@ -3021,33 +3021,29 @@ func (c *Core) LoadInFlightReqData() map[string]*InFlightReqData { // UpdateInFlightReqData updates the data for a specific reqID with // the clientID func (c *Core) UpdateInFlightReqData(reqID, clientID string) { - c.inFlightReqData.l.RLock() + c.inFlightReqData.l.Lock() + defer c.inFlightReqData.l.Unlock() v, ok := c.inFlightReqData.InFlightReqMap.Load(reqID) if !ok { - defer c.inFlightReqData.l.RUnlock() c.Logger().Trace("failed to retrieve request with ID %v", reqID) return } - c.inFlightReqData.l.RUnlock() reqData, _ := v.(*InFlightReqData) reqData.ClientID = clientID - c.inFlightReqData.l.Lock() - defer c.inFlightReqData.l.Unlock() c.inFlightReqData.InFlightReqMap.Store(reqID, reqData) } // LogCompletedRequests Logs the completed request to the server logs func (c *Core) LogCompletedRequests(reqID string, statusCode int) { logLevel := log.LevelFromString(c.logRequestsInfo.Load()) - c.inFlightReqData.l.RLock() + c.inFlightReqData.l.Lock() + defer c.inFlightReqData.l.Unlock() v, ok := c.inFlightReqData.InFlightReqMap.Load(reqID) if !ok { - defer c.inFlightReqData.l.RUnlock() c.logger.Log(logLevel, fmt.Sprintf("failed to retrieve request with ID %v", reqID)) return } - c.inFlightReqData.l.RUnlock() // there is only one writer to this map, so skip checking for errors reqData, _ := v.(*InFlightReqData) From 03153e72ae48c2fd12ca604f914db75420242254 Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Thu, 25 Nov 2021 13:45:28 -0800 Subject: [PATCH 23/33] another try to fix a data race --- vault/core.go | 7 +++---- 1 file changed, 3 insertions(+), 4 deletions(-) diff --git a/vault/core.go b/vault/core.go index 88102ea1854e..39b71dbaba65 100644 --- a/vault/core.go +++ b/vault/core.go @@ -3003,15 +3003,14 @@ func (c *Core) FinalizeInFlightReqData(reqID string, statusCode int) { // LoadInFlightReqData creates a snapshot map of the current // in-flight requests -func (c *Core) LoadInFlightReqData() map[string]*InFlightReqData { - currentInFlightReqMap := make(map[string]*InFlightReqData) +func (c *Core) LoadInFlightReqData() map[string]InFlightReqData { + currentInFlightReqMap := make(map[string]InFlightReqData) c.inFlightReqData.l.Lock() defer c.inFlightReqData.l.Unlock() c.inFlightReqData.InFlightReqMap.Range(func(key, value interface{}) bool { // there is only one writer to this map, so skip checking for errors v, _ := value.(*InFlightReqData) - currentInFlightReqMap[key.(string)] = v - + currentInFlightReqMap[key.(string)] = *v return true }) From da8a1e0087a735d73695a8bb0df0e3c5e43ef4bd Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Mon, 6 Dec 2021 10:59:26 -0800 Subject: [PATCH 24/33] addressing comments --- command/server/config.go | 9 +++--- http/sys_config_state_test.go | 2 +- sdk/logical/token.go | 59 +++++++++++++++++++++++++++++++-- sdk/logical/token_test.go | 60 ++++++++++++++++++++++++++++++++++ vault/activity_log.go | 56 -------------------------------- vault/activity_log_test.go | 8 ++--- vault/core.go | 21 ++++++------ vault/core_test.go | 61 ----------------------------------- vault/request_handling.go | 47 +-------------------------- vault/testing.go | 2 +- 10 files changed, 140 insertions(+), 185 deletions(-) diff --git a/command/server/config.go b/command/server/config.go index 93cc9c34f7e7..186b6468e2e3 100644 --- a/command/server/config.go +++ b/command/server/config.go @@ -12,6 +12,7 @@ import ( "strings" "time" + log "github.com/hashicorp/go-hclog" "github.com/hashicorp/go-multierror" "github.com/hashicorp/go-secure-stdlib/parseutil" "github.com/hashicorp/hcl" @@ -77,7 +78,7 @@ type Config struct { EnableResponseHeaderHostname bool `hcl:"-"` EnableResponseHeaderHostnameRaw interface{} `hcl:"enable_response_header_hostname"` - LogRequestsInfo string `hcl:"-"` + LogRequestsInfo log.Level `hcl:"-"` LogRequestsInfoRaw interface{} `hcl:"log_requests_info"` EnableResponseHeaderRaftNodeID bool `hcl:"-"` @@ -296,7 +297,7 @@ func (c *Config) Merge(c2 *Config) *Config { } result.LogRequestsInfo = c.LogRequestsInfo - if c2.LogRequestsInfo != "" { + if c2.LogRequestsInfo != log.NoLevel { result.LogRequestsInfo = c2.LogRequestsInfo } @@ -489,7 +490,7 @@ func ParseConfig(d, source string) (*Config, error) { } if result.LogRequestsInfoRaw != nil { - result.LogRequestsInfo = strings.ToLower(strings.TrimSpace(result.LogRequestsInfoRaw.(string))) + result.LogRequestsInfo = log.LevelFromString(strings.ToLower(strings.TrimSpace(result.LogRequestsInfoRaw.(string)))) result.LogRequestsInfoRaw = "" } @@ -854,7 +855,7 @@ func (c *Config) Sanitized() map[string]interface{} { "enable_response_header_raft_node_id": c.EnableResponseHeaderRaftNodeID, - "log_requests_info": c.LogRequestsInfo, + "log_requests_info": c.LogRequestsInfo.String(), } for k, v := range sharedResult { result[k] = v diff --git a/http/sys_config_state_test.go b/http/sys_config_state_test.go index ea34296a47bd..be011147bcfc 100644 --- a/http/sys_config_state_test.go +++ b/http/sys_config_state_test.go @@ -48,7 +48,7 @@ func TestSysConfigState_Sanitized(t *testing.T) { "plugin_directory": "", "enable_response_header_hostname": false, "enable_response_header_raft_node_id": false, - "log_requests_info": "", + "log_requests_info": "none", } expected = map[string]interface{}{ diff --git a/sdk/logical/token.go b/sdk/logical/token.go index 0586d768ead5..b204a4a6c8dd 100644 --- a/sdk/logical/token.go +++ b/sdk/logical/token.go @@ -1,7 +1,11 @@ package logical import ( + "crypto/sha256" + "encoding/base64" "fmt" + "sort" + "strings" "time" sockaddr "github.com/hashicorp/go-sockaddr" @@ -20,13 +24,24 @@ const ( // TokenTypeBatch is a batch token TokenTypeBatch - // TokenTypeDefaultService, configured on a mount, means that if + // TokenTypeDefaultService configured on a mount, means that if // TokenTypeDefault is sent back by the mount, create Service tokens TokenTypeDefaultService - // TokenTypeDefaultBatch, configured on a mount, means that if + // TokenTypeDefaultBatch configured on a mount, means that if // TokenTypeDefault is sent back by the mount, create Batch tokens TokenTypeDefaultBatch + + // ClientIDTWEDelimiter Delimiter between the string fields used to generate a client + // ID for tokens without entities. This is the 0 character, which + // is a non-printable string. Please see unicode.IsPrint for details. + ClientIDTWEDelimiter = rune('\x00') + + // SortedPoliciesTWEDelimiter Delimiter between each policy in the sorted policies used to + // generate a client ID for tokens without entities. This is the 127 + // character, which is a non-printable string. Please see unicode.IsPrint + // for details. + SortedPoliciesTWEDelimiter = rune('\x7F') ) func (t *TokenType) UnmarshalJSON(b []byte) error { @@ -154,6 +169,46 @@ type TokenEntry struct { CubbyholeID string `json:"cubbyhole_id" mapstructure:"cubbyhole_id" structs:"cubbyhole_id" sentinel:""` } +// CreateClientID returns the client ID, and a boolean which is false if the clientID +// has an entity, and true otherwise +func (te *TokenEntry) CreateClientID() (string, bool) { + var clientIDInputBuilder strings.Builder + + // if entry has an associated entity ID, return it + if te.EntityID != "" { + return te.EntityID, false + } + + // The entry is associated with a TWE (token without entity). In this case + // we must create a client ID by calculating the following formula: + // clientID = SHA256(sorted policies + namespace) + + // Step 1: Copy entry policies to a new struct + sortedPolicies := make([]string, len(te.Policies)) + copy(sortedPolicies, te.Policies) + + // Step 2: Sort and join copied policies + sort.Strings(sortedPolicies) + for _, pol := range sortedPolicies { + clientIDInputBuilder.WriteRune(SortedPoliciesTWEDelimiter) + clientIDInputBuilder.WriteString(pol) + } + + // Step 3: Add namespace ID + clientIDInputBuilder.WriteRune(ClientIDTWEDelimiter) + clientIDInputBuilder.WriteString(te.NamespaceID) + + if clientIDInputBuilder.Len() == 0 { + return "", true + } + // Step 4: Remove the first character in the string, as it's an unnecessary delimiter + clientIDInput := clientIDInputBuilder.String()[1:] + + // Step 5: Hash the sum + hashed := sha256.Sum256([]byte(clientIDInput)) + return base64.StdEncoding.EncodeToString(hashed[:]), true +} + func (te *TokenEntry) SentinelGet(key string) (interface{}, error) { if te == nil { return nil, nil diff --git a/sdk/logical/token_test.go b/sdk/logical/token_test.go index 5499e5c5bd14..e44c707a5165 100644 --- a/sdk/logical/token_test.go +++ b/sdk/logical/token_test.go @@ -1,6 +1,8 @@ package logical import ( + "crypto/sha256" + "encoding/base64" "encoding/json" "testing" ) @@ -41,3 +43,61 @@ func TestJSONSerialization(t *testing.T) { t.Fatalf("expected %v, got %v", tt, utt) } } + +// TestCreateClientID verifies that CreateClientID uses the entity ID for a token +// entry if one exists, and creates an appropriate client ID otherwise. +func TestCreateClientID(t *testing.T) { + entry := TokenEntry{NamespaceID: "namespaceFoo", Policies: []string{"bar", "baz", "foo", "banana"}} + id, isTWE := entry.CreateClientID() + if !isTWE { + t.Fatalf("TWE token should return true value in isTWE bool") + } + expectedIDPlaintext := "banana" + string(SortedPoliciesTWEDelimiter) + "bar" + + string(SortedPoliciesTWEDelimiter) + "baz" + + string(SortedPoliciesTWEDelimiter) + "foo" + string(ClientIDTWEDelimiter) + "namespaceFoo" + + hashed := sha256.Sum256([]byte(expectedIDPlaintext)) + expectedID := base64.StdEncoding.EncodeToString(hashed[:]) + if expectedID != id { + t.Fatalf("wrong ID: expected %s, found %s", expectedID, id) + } + // Test with entityID + entry = TokenEntry{EntityID: "entityFoo", NamespaceID: "namespaceFoo", Policies: []string{"bar", "baz", "foo", "banana"}} + id, isTWE = entry.CreateClientID() + if isTWE { + t.Fatalf("token with entity should return false value in isTWE bool") + } + if id != "entityFoo" { + t.Fatalf("client ID should be entity ID") + } + + // Test without namespace + entry = TokenEntry{Policies: []string{"bar", "baz", "foo", "banana"}} + id, isTWE = entry.CreateClientID() + if !isTWE { + t.Fatalf("TWE token should return true value in isTWE bool") + } + expectedIDPlaintext = "banana" + string(SortedPoliciesTWEDelimiter) + "bar" + + string(SortedPoliciesTWEDelimiter) + "baz" + + string(SortedPoliciesTWEDelimiter) + "foo" + string(ClientIDTWEDelimiter) + + hashed = sha256.Sum256([]byte(expectedIDPlaintext)) + expectedID = base64.StdEncoding.EncodeToString(hashed[:]) + if expectedID != id { + t.Fatalf("wrong ID: expected %s, found %s", expectedID, id) + } + + // Test without policies + entry = TokenEntry{NamespaceID: "namespaceFoo"} + id, isTWE = entry.CreateClientID() + if !isTWE { + t.Fatalf("TWE token should return true value in isTWE bool") + } + expectedIDPlaintext = "namespaceFoo" + + hashed = sha256.Sum256([]byte(expectedIDPlaintext)) + expectedID = base64.StdEncoding.EncodeToString(hashed[:]) + if expectedID != id { + t.Fatalf("wrong ID: expected %s, found %s", expectedID, id) + } +} diff --git a/vault/activity_log.go b/vault/activity_log.go index c279ff3ed018..85a7b311d014 100644 --- a/vault/activity_log.go +++ b/vault/activity_log.go @@ -2,8 +2,6 @@ package vault import ( "context" - "crypto/sha256" - "encoding/base64" "encoding/json" "errors" "fmt" @@ -63,17 +61,6 @@ const ( // Estimates as 8KiB / 64 bytes = 128 activityFragmentStandbyCapacity = 128 - // Delimiter between the string fields used to generate a client - // ID for tokens without entities. This is the 0 character, which - // is a non-printable string. Please see unicode.IsPrint for details. - clientIDTWEDelimiter = rune('\x00') - - // Delimiter between each policy in the sorted policies used to - // generate a client ID for tokens without entities. This is the 127 - // character, which is a non-printable string. Please see unicode.IsPrint - // for details. - sortedPoliciesTWEDelimiter = rune('\x7F') - // trackedTWESegmentPeriod is a time period of a little over a month, and represents // the amount of time that needs to pass after a 1.9 or later upgrade to result in // all fragments and segments no longer storing token counts in the directtokens @@ -1591,7 +1578,6 @@ func (a *ActivityLog) loadConfigOrDefault(ctx context.Context) (activityConfig, } // HandleTokenUsage adds the TokenEntry to the current fragment of the activity log -// and returns the corresponding Client ID. // This currently occurs on token usage only. func (a *ActivityLog) HandleTokenUsage(entry *logical.TokenEntry, clientID string, isTWE bool) { // First, check if a is enabled, so as to avoid the cost of creating an ID for @@ -1617,48 +1603,6 @@ func (a *ActivityLog) HandleTokenUsage(entry *logical.TokenEntry, clientID strin a.AddClientToFragment(clientID, entry.NamespaceID, entry.CreationTime, isTWE) } -// CreateClientID returns the client ID, and a boolean which is false if the clientID -// has an entity, and true otherwise -func (a *ActivityLog) CreateClientID(entry *logical.TokenEntry) (string, bool) { - var clientIDInputBuilder strings.Builder - - // if entry has an associated entity ID, return it - if entry.EntityID != "" { - return entry.EntityID, false - } - - // The entry is associated with a TWE (token without entity). In this case - // we must create a client ID by calculating the following formula: - // clientID = SHA256(sorted policies + namespace) - - // Step 1: Copy entry policies to a new struct - sortedPolicies := make([]string, len(entry.Policies)) - copy(sortedPolicies, entry.Policies) - - // Step 2: Sort and join copied policies - sort.Strings(sortedPolicies) - for _, pol := range sortedPolicies { - clientIDInputBuilder.WriteRune(sortedPoliciesTWEDelimiter) - clientIDInputBuilder.WriteString(pol) - } - - // Step 3: Add namespace ID - clientIDInputBuilder.WriteRune(clientIDTWEDelimiter) - clientIDInputBuilder.WriteString(entry.NamespaceID) - - if clientIDInputBuilder.Len() == 0 { - a.logger.Error("vault token with no entity ID, policies, or namespace was recorded " + - "in the activity log") - return "", true - } - // Step 4: Remove the first character in the string, as it's an unnecessary delimiter - clientIDInput := clientIDInputBuilder.String()[1:] - - // Step 5: Hash the sum - hashed := sha256.Sum256([]byte(clientIDInput)) - return base64.StdEncoding.EncodeToString(hashed[:]), true -} - func (a *ActivityLog) namespaceToLabel(ctx context.Context, nsID string) string { ns, err := NamespaceByID(ctx, nsID, a.core) if err != nil || ns == nil { diff --git a/vault/activity_log_test.go b/vault/activity_log_test.go index 743a9ea601ca..5a027c88eec4 100644 --- a/vault/activity_log_test.go +++ b/vault/activity_log_test.go @@ -120,7 +120,7 @@ func TestActivityLog_Creation_WrappingTokens(t *testing.T) { NamespaceID: namespace_id, } - id, isTWE := core.CreateClientID(te) + id, isTWE := te.CreateClientID() a.HandleTokenUsage(te, id, isTWE) a.fragmentLock.Lock() @@ -137,7 +137,7 @@ func TestActivityLog_Creation_WrappingTokens(t *testing.T) { NamespaceID: namespace_id, } - id, isTWE = core.CreateClientID(teNew) + id, isTWE = teNew.CreateClientID() a.HandleTokenUsage(teNew, id, isTWE) a.fragmentLock.Lock() @@ -363,13 +363,13 @@ func TestActivityLog_SaveTokensToStorageDoesNotUpdateTokenCount(t *testing.T) { tokenEntryOne := logical.TokenEntry{NamespaceID: "ns1_id", Policies: []string{"hi"}} entityEntry := logical.TokenEntry{EntityID: "foo", NamespaceID: "ns1_id", Policies: []string{"hi"}} - idNonEntity, isTWE := core.CreateClientID(&tokenEntryOne) + idNonEntity, isTWE := tokenEntryOne.CreateClientID() for i := 0; i < 3; i++ { a.HandleTokenUsage(&tokenEntryOne, idNonEntity, isTWE) } - idEntity, isTWE := core.CreateClientID(&entityEntry) + idEntity, isTWE := entityEntry.CreateClientID() for i := 0; i < 2; i++ { a.HandleTokenUsage(&entityEntry, idEntity, isTWE) } diff --git a/vault/core.go b/vault/core.go index 39b71dbaba65..18a1d3278bbb 100644 --- a/vault/core.go +++ b/vault/core.go @@ -390,7 +390,7 @@ type Core struct { physicalCache physical.ToggleablePurgemonster // logRequestsInfo indicates at which level requests should be logged - logRequestsInfo uberAtomic.String + logRequestsInfo *uberAtomic.Int32 // reloadFuncs is a map containing reload functions reloadFuncs map[string][]reloadutil.ReloadFunc @@ -1038,10 +1038,11 @@ func NewCore(conf *CoreConfig) (*Core, error) { c.customListenerHeader.Store(([]*ListenerCustomHeaders)(nil)) } + c.logRequestsInfo = uberAtomic.NewInt32(0) switch { - case log.LevelFromString(conf.RawConfig.LogRequestsInfo) > log.NoLevel && log.LevelFromString(conf.RawConfig.LogRequestsInfo) < log.Off: - c.logRequestsInfo.Store(conf.RawConfig.LogRequestsInfo) - case conf.RawConfig.LogRequestsInfo != "": + case conf.RawConfig.LogRequestsInfo > log.NoLevel && conf.RawConfig.LogRequestsInfo < log.Off: + c.logRequestsInfo.Store(int32(conf.RawConfig.LogRequestsInfo)) + default: c.logger.Warn("invalid log_requests_info", "level", conf.RawConfig.LogRequestsInfo) } @@ -2991,7 +2992,7 @@ func (c *Core) StoreInFlightReqData(reqID string, data *InFlightReqData) { // request from the inFlightReqMap and decrement the number of in-flight // requests by one. func (c *Core) FinalizeInFlightReqData(reqID string, statusCode int) { - if c.logRequestsInfo.Load() != "" { + if c.logRequestsInfo.Load() != 0 { c.LogCompletedRequests(reqID, statusCode) } @@ -3035,7 +3036,7 @@ func (c *Core) UpdateInFlightReqData(reqID, clientID string) { // LogCompletedRequests Logs the completed request to the server logs func (c *Core) LogCompletedRequests(reqID string, statusCode int) { - logLevel := log.LevelFromString(c.logRequestsInfo.Load()) + logLevel := log.Level(c.logRequestsInfo.Load()) c.inFlightReqData.l.Lock() defer c.inFlightReqData.l.Unlock() v, ok := c.inFlightReqData.InFlightReqMap.Load(reqID) @@ -3056,9 +3057,9 @@ func (c *Core) ReloadLogRequestsInfo(){ } infoLevel := conf.(*server.Config).LogRequestsInfo switch { - case log.LevelFromString(infoLevel) > log.NoLevel && log.LevelFromString(infoLevel) < log.Off: - c.logRequestsInfo.Store(infoLevel) - case infoLevel != "": - c.logger.Warn("invalid log_requests_info", "level", infoLevel) + case infoLevel > log.NoLevel && infoLevel < log.Off: + c.logRequestsInfo.Store(int32(infoLevel)) + default: + c.logger.Warn("invalid log_requests_info", "level", infoLevel.String()) } } diff --git a/vault/core_test.go b/vault/core_test.go index d849c748bc02..157d6db1e38c 100644 --- a/vault/core_test.go +++ b/vault/core_test.go @@ -2,8 +2,6 @@ package vault import ( "context" - "crypto/sha256" - "encoding/base64" "fmt" "reflect" "sync" @@ -2596,62 +2594,3 @@ func TestCore_ServiceRegistration(t *testing.T) { t.Fatal(diff) } } - -// TestCreateClientID verifies that CreateClientID uses the entity ID for a token -// entry if one exists, and creates an appropriate client ID otherwise. -func TestCreateClientID(t *testing.T) { - entry := logical.TokenEntry{NamespaceID: "namespaceFoo", Policies: []string{"bar", "baz", "foo", "banana"}} - core := Core{} - id, isTWE := core.CreateClientID(&entry) - if !isTWE { - t.Fatalf("TWE token should return true value in isTWE bool") - } - expectedIDPlaintext := "banana" + string(sortedPoliciesTWEDelimiter) + "bar" + - string(sortedPoliciesTWEDelimiter) + "baz" + - string(sortedPoliciesTWEDelimiter) + "foo" + string(clientIDTWEDelimiter) + "namespaceFoo" - - hashed := sha256.Sum256([]byte(expectedIDPlaintext)) - expectedID := base64.StdEncoding.EncodeToString(hashed[:]) - if expectedID != id { - t.Fatalf("wrong ID: expected %s, found %s", expectedID, id) - } - // Test with entityID - entry = logical.TokenEntry{EntityID: "entityFoo", NamespaceID: "namespaceFoo", Policies: []string{"bar", "baz", "foo", "banana"}} - id, isTWE = core.CreateClientID(&entry) - if isTWE { - t.Fatalf("token with entity should return false value in isTWE bool") - } - if id != "entityFoo" { - t.Fatalf("client ID should be entity ID") - } - - // Test without namespace - entry = logical.TokenEntry{Policies: []string{"bar", "baz", "foo", "banana"}} - id, isTWE = core.CreateClientID(&entry) - if !isTWE { - t.Fatalf("TWE token should return true value in isTWE bool") - } - expectedIDPlaintext = "banana" + string(sortedPoliciesTWEDelimiter) + "bar" + - string(sortedPoliciesTWEDelimiter) + "baz" + - string(sortedPoliciesTWEDelimiter) + "foo" + string(clientIDTWEDelimiter) - - hashed = sha256.Sum256([]byte(expectedIDPlaintext)) - expectedID = base64.StdEncoding.EncodeToString(hashed[:]) - if expectedID != id { - t.Fatalf("wrong ID: expected %s, found %s", expectedID, id) - } - - // Test without policies - entry = logical.TokenEntry{NamespaceID: "namespaceFoo"} - id, isTWE = core.CreateClientID(&entry) - if !isTWE { - t.Fatalf("TWE token should return true value in isTWE bool") - } - expectedIDPlaintext = "namespaceFoo" - - hashed = sha256.Sum256([]byte(expectedIDPlaintext)) - expectedID = base64.StdEncoding.EncodeToString(hashed[:]) - if expectedID != id { - t.Fatalf("wrong ID: expected %s, found %s", expectedID, id) - } -} diff --git a/vault/request_handling.go b/vault/request_handling.go index e7f82aac916f..ddef97f5ecc2 100644 --- a/vault/request_handling.go +++ b/vault/request_handling.go @@ -2,11 +2,8 @@ package vault import ( "context" - "crypto/sha256" - "encoding/base64" "errors" "fmt" - "sort" "strings" "time" @@ -367,7 +364,7 @@ func (c *Core) checkToken(ctx context.Context, req *logical.Request, unauth bool if te.CreationTime > 0 { auth.IssueTime = time.Unix(te.CreationTime, 0) } - clientID, isTWE = c.CreateClientID(te) + clientID, isTWE = te.CreateClientID() req.ClientID = clientID } @@ -410,48 +407,6 @@ func (c *Core) checkToken(ctx context.Context, req *logical.Request, unauth bool return auth, te, nil } -// CreateClientID returns the client ID, and a boolean which is false if the clientID -// has an entity, and true otherwise -func (c *Core) CreateClientID(entry *logical.TokenEntry) (string, bool) { - var clientIDInputBuilder strings.Builder - - // if entry has an associated entity ID, return it - if entry.EntityID != "" { - return entry.EntityID, false - } - - // The entry is associated with a TWE (token without entity). In this case - // we must create a client ID by calculating the following formula: - // clientID = SHA256(sorted policies + namespace) - - // Step 1: Copy entry policies to a new struct - sortedPolicies := make([]string, len(entry.Policies)) - copy(sortedPolicies, entry.Policies) - - // Step 2: Sort and join copied policies - sort.Strings(sortedPolicies) - for _, pol := range sortedPolicies { - clientIDInputBuilder.WriteRune(sortedPoliciesTWEDelimiter) - clientIDInputBuilder.WriteString(pol) - } - - // Step 3: Add namespace ID - clientIDInputBuilder.WriteRune(clientIDTWEDelimiter) - clientIDInputBuilder.WriteString(entry.NamespaceID) - - if clientIDInputBuilder.Len() == 0 { - c.logger.Error("vault token with no entity ID, policies, or namespace was recorded " + - "in the activity log") - return "", true - } - // Step 4: Remove the first character in the string, as it's an unnecessary delimiter - clientIDInput := clientIDInputBuilder.String()[1:] - - // Step 5: Hash the sum - hashed := sha256.Sum256([]byte(clientIDInput)) - return base64.StdEncoding.EncodeToString(hashed[:]), true -} - // HandleRequest is used to handle a new incoming request func (c *Core) HandleRequest(httpCtx context.Context, req *logical.Request) (resp *logical.Response, err error) { return c.switchedLockHandleRequest(httpCtx, req, true) diff --git a/vault/testing.go b/vault/testing.go index 8804def8ba0c..2db3b3bacb8b 100644 --- a/vault/testing.go +++ b/vault/testing.go @@ -130,7 +130,7 @@ func TestCoreWithSeal(t testing.T, testSeal Seal, enableRaw bool) *Core { func TestCoreWithCustomResponseHeaderAndUI(t testing.T, CustomResponseHeaders map[string]map[string]string, enableUI bool) (*Core, [][]byte, string) { confRaw := &server.Config{ - LogRequestsInfo: "basic", + LogRequestsInfo: log.NoLevel, SharedConfig: &configutil.SharedConfig{ Listeners: []*configutil.Listener{ { From 2a538240c50f0ec2232a69bb6bb7eccc39fcdba1 Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Mon, 6 Dec 2021 11:49:21 -0800 Subject: [PATCH 25/33] fixing couple of tests --- command/server/config_test_helpers.go | 2 +- vault/core.go | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/command/server/config_test_helpers.go b/command/server/config_test_helpers.go index b09881260290..8246e2bd226f 100644 --- a/command/server/config_test_helpers.go +++ b/command/server/config_test_helpers.go @@ -701,7 +701,7 @@ func testConfig_Sanitized(t *testing.T) { "enable_ui": true, "enable_response_header_hostname": false, "enable_response_header_raft_node_id": false, - "log_requests_info": "basic", + "log_requests_info": "none", "ha_storage": map[string]interface{}{ "cluster_addr": "top_level_cluster_addr", "disable_clustering": true, diff --git a/vault/core.go b/vault/core.go index ad37f5b7f76b..10c567a3d6d8 100644 --- a/vault/core.go +++ b/vault/core.go @@ -2992,7 +2992,7 @@ func (c *Core) StoreInFlightReqData(reqID string, data *InFlightReqData) { // request from the inFlightReqMap and decrement the number of in-flight // requests by one. func (c *Core) FinalizeInFlightReqData(reqID string, statusCode int) { - if c.logRequestsInfo.Load() != 0 { + if c.logRequestsInfo != nil && c.logRequestsInfo.Load() != 0 { c.LogCompletedRequests(reqID, statusCode) } From 9893d2ec53a60f4fdbbf2cef18017e7c30a7c82e Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Mon, 6 Dec 2021 13:04:05 -0800 Subject: [PATCH 26/33] changing log_requests_info to log_requests_level --- command/server.go | 2 +- command/server/config.go | 19 +++++++++--------- command/server/config_test_helpers.go | 2 +- command/server/test-fixtures/config3.hcl | 2 +- http/sys_config_state_test.go | 2 +- vault/core.go | 25 ++++++++++++------------ vault/testing.go | 2 +- 7 files changed, 27 insertions(+), 27 deletions(-) diff --git a/command/server.go b/command/server.go index 5098f300f816..5b8eb634af8e 100644 --- a/command/server.go +++ b/command/server.go @@ -1548,7 +1548,7 @@ func (c *ServerCommand) Run(args []string) int { } // Setting log request with the new value in the config after reload - core.ReloadLogRequestsInfo() + core.ReloadLogRequestsLevel() if config.LogLevel != "" { configLogLevel := strings.ToLower(strings.TrimSpace(config.LogLevel)) diff --git a/command/server/config.go b/command/server/config.go index 186b6468e2e3..72c96367f724 100644 --- a/command/server/config.go +++ b/command/server/config.go @@ -12,7 +12,6 @@ import ( "strings" "time" - log "github.com/hashicorp/go-hclog" "github.com/hashicorp/go-multierror" "github.com/hashicorp/go-secure-stdlib/parseutil" "github.com/hashicorp/hcl" @@ -78,8 +77,8 @@ type Config struct { EnableResponseHeaderHostname bool `hcl:"-"` EnableResponseHeaderHostnameRaw interface{} `hcl:"enable_response_header_hostname"` - LogRequestsInfo log.Level `hcl:"-"` - LogRequestsInfoRaw interface{} `hcl:"log_requests_info"` + LogRequestsLevel string `hcl:"-"` + LogRequestsLevelRaw interface{} `hcl:"log_requests_level"` EnableResponseHeaderRaftNodeID bool `hcl:"-"` EnableResponseHeaderRaftNodeIDRaw interface{} `hcl:"enable_response_header_raft_node_id"` @@ -296,9 +295,9 @@ func (c *Config) Merge(c2 *Config) *Config { result.EnableResponseHeaderHostname = c2.EnableResponseHeaderHostname } - result.LogRequestsInfo = c.LogRequestsInfo - if c2.LogRequestsInfo != log.NoLevel { - result.LogRequestsInfo = c2.LogRequestsInfo + result.LogRequestsLevel = c.LogRequestsLevel + if c2.LogRequestsLevel != "" { + result.LogRequestsLevel = c2.LogRequestsLevel } result.EnableResponseHeaderRaftNodeID = c.EnableResponseHeaderRaftNodeID @@ -489,9 +488,9 @@ func ParseConfig(d, source string) (*Config, error) { } } - if result.LogRequestsInfoRaw != nil { - result.LogRequestsInfo = log.LevelFromString(strings.ToLower(strings.TrimSpace(result.LogRequestsInfoRaw.(string)))) - result.LogRequestsInfoRaw = "" + if result.LogRequestsLevelRaw != nil { + result.LogRequestsLevel = strings.ToLower(strings.TrimSpace(result.LogRequestsLevelRaw.(string))) + result.LogRequestsLevelRaw = "" } if result.EnableResponseHeaderRaftNodeIDRaw != nil { @@ -855,7 +854,7 @@ func (c *Config) Sanitized() map[string]interface{} { "enable_response_header_raft_node_id": c.EnableResponseHeaderRaftNodeID, - "log_requests_info": c.LogRequestsInfo.String(), + "log_requests_level": c.LogRequestsLevel, } for k, v := range sharedResult { result[k] = v diff --git a/command/server/config_test_helpers.go b/command/server/config_test_helpers.go index 8246e2bd226f..97c1f93821cf 100644 --- a/command/server/config_test_helpers.go +++ b/command/server/config_test_helpers.go @@ -701,7 +701,7 @@ func testConfig_Sanitized(t *testing.T) { "enable_ui": true, "enable_response_header_hostname": false, "enable_response_header_raft_node_id": false, - "log_requests_info": "none", + "log_requests_level": "", "ha_storage": map[string]interface{}{ "cluster_addr": "top_level_cluster_addr", "disable_clustering": true, diff --git a/command/server/test-fixtures/config3.hcl b/command/server/test-fixtures/config3.hcl index 9de5c83d46bb..1a4894d194bc 100644 --- a/command/server/test-fixtures/config3.hcl +++ b/command/server/test-fixtures/config3.hcl @@ -1,6 +1,6 @@ disable_cache = true disable_mlock = true -log_requests_info = "Basic" +log_requests_level = "Basic" ui = true diff --git a/http/sys_config_state_test.go b/http/sys_config_state_test.go index be011147bcfc..2abdf38e65fb 100644 --- a/http/sys_config_state_test.go +++ b/http/sys_config_state_test.go @@ -48,7 +48,7 @@ func TestSysConfigState_Sanitized(t *testing.T) { "plugin_directory": "", "enable_response_header_hostname": false, "enable_response_header_raft_node_id": false, - "log_requests_info": "none", + "log_requests_level": "", } expected = map[string]interface{}{ diff --git a/vault/core.go b/vault/core.go index 10c567a3d6d8..36f3e3aa0f3a 100644 --- a/vault/core.go +++ b/vault/core.go @@ -389,8 +389,8 @@ type Core struct { // disabled physicalCache physical.ToggleablePurgemonster - // logRequestsInfo indicates at which level requests should be logged - logRequestsInfo *uberAtomic.Int32 + // logRequestsLevel indicates at which level requests should be logged + logRequestsLevel *uberAtomic.Int32 // reloadFuncs is a map containing reload functions reloadFuncs map[string][]reloadutil.ReloadFunc @@ -1038,12 +1038,13 @@ func NewCore(conf *CoreConfig) (*Core, error) { c.customListenerHeader.Store(([]*ListenerCustomHeaders)(nil)) } - c.logRequestsInfo = uberAtomic.NewInt32(0) + logRequestsLevel := log.LevelFromString(conf.RawConfig.LogRequestsLevel) + c.logRequestsLevel = uberAtomic.NewInt32(0) switch { - case conf.RawConfig.LogRequestsInfo > log.NoLevel && conf.RawConfig.LogRequestsInfo < log.Off: - c.logRequestsInfo.Store(int32(conf.RawConfig.LogRequestsInfo)) + case logRequestsLevel > log.NoLevel && logRequestsLevel < log.Off: + c.logRequestsLevel.Store(int32(logRequestsLevel)) default: - c.logger.Warn("invalid log_requests_info", "level", conf.RawConfig.LogRequestsInfo) + c.logger.Warn("invalid log_requests_level", "level", conf.RawConfig.LogRequestsLevel) } quotasLogger := conf.Logger.Named("quotas") @@ -2992,7 +2993,7 @@ func (c *Core) StoreInFlightReqData(reqID string, data *InFlightReqData) { // request from the inFlightReqMap and decrement the number of in-flight // requests by one. func (c *Core) FinalizeInFlightReqData(reqID string, statusCode int) { - if c.logRequestsInfo != nil && c.logRequestsInfo.Load() != 0 { + if c.logRequestsLevel != nil && c.logRequestsLevel.Load() != 0 { c.LogCompletedRequests(reqID, statusCode) } @@ -3036,7 +3037,7 @@ func (c *Core) UpdateInFlightReqData(reqID, clientID string) { // LogCompletedRequests Logs the completed request to the server logs func (c *Core) LogCompletedRequests(reqID string, statusCode int) { - logLevel := log.Level(c.logRequestsInfo.Load()) + logLevel := log.Level(c.logRequestsLevel.Load()) c.inFlightReqData.l.Lock() defer c.inFlightReqData.l.Unlock() v, ok := c.inFlightReqData.InFlightReqMap.Load(reqID) @@ -3050,17 +3051,17 @@ func (c *Core) LogCompletedRequests(reqID string, statusCode int) { c.logger.Log(logLevel, "completed_request","client_id", reqData.ClientID, "client_address", reqData.ClientRemoteAddr, "status_code", statusCode, "request_path", reqData.ReqPath, "request_method", reqData.Method) } -func (c *Core) ReloadLogRequestsInfo() { +func (c *Core) ReloadLogRequestsLevel() { conf := c.rawConfig.Load() if conf == nil { return } - infoLevel := conf.(*server.Config).LogRequestsInfo + infoLevel := log.LevelFromString(conf.(*server.Config).LogRequestsLevel) switch { case infoLevel > log.NoLevel && infoLevel < log.Off: - c.logRequestsInfo.Store(int32(infoLevel)) + c.logRequestsLevel.Store(int32(infoLevel)) default: - c.logger.Warn("invalid log_requests_info", "level", infoLevel.String()) + c.logger.Warn("invalid log_requests_level", "level", infoLevel.String()) } } diff --git a/vault/testing.go b/vault/testing.go index be98887a0744..3a2f0ab8eeac 100644 --- a/vault/testing.go +++ b/vault/testing.go @@ -130,7 +130,7 @@ func TestCoreWithSeal(t testing.T, testSeal Seal, enableRaw bool) *Core { func TestCoreWithCustomResponseHeaderAndUI(t testing.T, CustomResponseHeaders map[string]map[string]string, enableUI bool) (*Core, [][]byte, string) { confRaw := &server.Config{ - LogRequestsInfo: log.NoLevel, + LogRequestsLevel: "basic", SharedConfig: &configutil.SharedConfig{ Listeners: []*configutil.Listener{ { From d565b64f8ac4d6d9d7429bbd30cd6147cbc6deda Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Mon, 6 Dec 2021 13:06:35 -0800 Subject: [PATCH 27/33] minor style change --- command/server/config.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/command/server/config.go b/command/server/config.go index 72c96367f724..c9f48e41d2ab 100644 --- a/command/server/config.go +++ b/command/server/config.go @@ -77,7 +77,7 @@ type Config struct { EnableResponseHeaderHostname bool `hcl:"-"` EnableResponseHeaderHostnameRaw interface{} `hcl:"enable_response_header_hostname"` - LogRequestsLevel string `hcl:"-"` + LogRequestsLevel string `hcl:"-"` LogRequestsLevelRaw interface{} `hcl:"log_requests_level"` EnableResponseHeaderRaftNodeID bool `hcl:"-"` From 97c4cf39020077a6acf7b8ec7d5e7e69d8ea795f Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Mon, 6 Dec 2021 13:36:08 -0800 Subject: [PATCH 28/33] fixing a test --- command/server/config_test_helpers.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/command/server/config_test_helpers.go b/command/server/config_test_helpers.go index 97c1f93821cf..662d77635357 100644 --- a/command/server/config_test_helpers.go +++ b/command/server/config_test_helpers.go @@ -701,7 +701,7 @@ func testConfig_Sanitized(t *testing.T) { "enable_ui": true, "enable_response_header_hostname": false, "enable_response_header_raft_node_id": false, - "log_requests_level": "", + "log_requests_level": "basic", "ha_storage": map[string]interface{}{ "cluster_addr": "top_level_cluster_addr", "disable_clustering": true, From 5649a60af601713bd561bb5b252fead88777e2ed Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Tue, 7 Dec 2021 09:00:16 -0800 Subject: [PATCH 29/33] removing the lock in InFlightRequests --- http/handler.go | 2 +- vault/core.go | 40 +++++++++++++++------------------------- 2 files changed, 16 insertions(+), 26 deletions(-) diff --git a/http/handler.go b/http/handler.go index e45eb436b491..636566a535c5 100644 --- a/http/handler.go +++ b/http/handler.go @@ -402,7 +402,7 @@ func wrapGenericHandler(core *vault.Core, h http.Handler, props *vault.HandlerPr // Storing the in-flight requests. Path should include namespace as well core.StoreInFlightReqData( inFlightReqID, - &vault.InFlightReqData { + vault.InFlightReqData { StartTime: inFlightReqStartTime, ReqPath: r.URL.Path, ClientRemoteAddr: clientAddr, diff --git a/vault/core.go b/vault/core.go index 36f3e3aa0f3a..d6da3656664a 100644 --- a/vault/core.go +++ b/vault/core.go @@ -1038,12 +1038,12 @@ func NewCore(conf *CoreConfig) (*Core, error) { c.customListenerHeader.Store(([]*ListenerCustomHeaders)(nil)) } - logRequestsLevel := log.LevelFromString(conf.RawConfig.LogRequestsLevel) + logRequestsLevel := conf.RawConfig.LogRequestsLevel c.logRequestsLevel = uberAtomic.NewInt32(0) switch { - case logRequestsLevel > log.NoLevel && logRequestsLevel < log.Off: - c.logRequestsLevel.Store(int32(logRequestsLevel)) - default: + case log.LevelFromString(logRequestsLevel) > log.NoLevel && log.LevelFromString(logRequestsLevel) < log.Off: + c.logRequestsLevel.Store(int32(log.LevelFromString(logRequestsLevel))) + case logRequestsLevel != "": c.logger.Warn("invalid log_requests_level", "level", conf.RawConfig.LogRequestsLevel) } @@ -2968,7 +2968,6 @@ type LicenseState struct { } type InFlightRequests struct { - l sync.RWMutex InFlightReqMap *sync.Map InFlightReqCount *uberAtomic.Uint64 } @@ -2981,9 +2980,7 @@ type InFlightReqData struct { ClientID string `json:"client_id"` } -func (c *Core) StoreInFlightReqData(reqID string, data *InFlightReqData) { - c.inFlightReqData.l.Lock() - defer c.inFlightReqData.l.Unlock() +func (c *Core) StoreInFlightReqData(reqID string, data InFlightReqData) { c.inFlightReqData.InFlightReqMap.Store(reqID, data) c.inFlightReqData.InFlightReqCount.Inc() } @@ -2997,8 +2994,6 @@ func (c *Core) FinalizeInFlightReqData(reqID string, statusCode int) { c.LogCompletedRequests(reqID, statusCode) } - c.inFlightReqData.l.Lock() - defer c.inFlightReqData.l.Unlock() c.inFlightReqData.InFlightReqMap.Delete(reqID) c.inFlightReqData.InFlightReqCount.Dec() } @@ -3007,12 +3002,10 @@ func (c *Core) FinalizeInFlightReqData(reqID string, statusCode int) { // in-flight requests func (c *Core) LoadInFlightReqData() map[string]InFlightReqData { currentInFlightReqMap := make(map[string]InFlightReqData) - c.inFlightReqData.l.Lock() - defer c.inFlightReqData.l.Unlock() c.inFlightReqData.InFlightReqMap.Range(func(key, value interface{}) bool { // there is only one writer to this map, so skip checking for errors - v, _ := value.(*InFlightReqData) - currentInFlightReqMap[key.(string)] = *v + v, _ := value.(InFlightReqData) + currentInFlightReqMap[key.(string)] = v return true }) @@ -3022,15 +3015,13 @@ func (c *Core) LoadInFlightReqData() map[string]InFlightReqData { // UpdateInFlightReqData updates the data for a specific reqID with // the clientID func (c *Core) UpdateInFlightReqData(reqID, clientID string) { - c.inFlightReqData.l.Lock() - defer c.inFlightReqData.l.Unlock() v, ok := c.inFlightReqData.InFlightReqMap.Load(reqID) if !ok { c.Logger().Trace("failed to retrieve request with ID %v", reqID) return } - reqData, _ := v.(*InFlightReqData) + reqData, _ := v.(InFlightReqData) reqData.ClientID = clientID c.inFlightReqData.InFlightReqMap.Store(reqID, reqData) } @@ -3038,8 +3029,6 @@ func (c *Core) UpdateInFlightReqData(reqID, clientID string) { // LogCompletedRequests Logs the completed request to the server logs func (c *Core) LogCompletedRequests(reqID string, statusCode int) { logLevel := log.Level(c.logRequestsLevel.Load()) - c.inFlightReqData.l.Lock() - defer c.inFlightReqData.l.Unlock() v, ok := c.inFlightReqData.InFlightReqMap.Load(reqID) if !ok { c.logger.Log(logLevel, fmt.Sprintf("failed to retrieve request with ID %v", reqID)) @@ -3047,7 +3036,7 @@ func (c *Core) LogCompletedRequests(reqID string, statusCode int) { } // there is only one writer to this map, so skip checking for errors - reqData, _ := v.(*InFlightReqData) + reqData, _ := v.(InFlightReqData) c.logger.Log(logLevel, "completed_request","client_id", reqData.ClientID, "client_address", reqData.ClientRemoteAddr, "status_code", statusCode, "request_path", reqData.ReqPath, "request_method", reqData.Method) } @@ -3056,12 +3045,13 @@ func (c *Core) ReloadLogRequestsLevel() { if conf == nil { return } - infoLevel := log.LevelFromString(conf.(*server.Config).LogRequestsLevel) + + infoLevel := conf.(*server.Config).LogRequestsLevel switch { - case infoLevel > log.NoLevel && infoLevel < log.Off: - c.logRequestsLevel.Store(int32(infoLevel)) - default: - c.logger.Warn("invalid log_requests_level", "level", infoLevel.String()) + case log.LevelFromString(infoLevel) > log.NoLevel && log.LevelFromString(infoLevel) < log.Off: + c.logRequestsLevel.Store(int32(log.LevelFromString(infoLevel))) + case infoLevel != "": + c.logger.Warn("invalid log_requests_level", "level", infoLevel) } } From a0bec8dda92abc511063d0074c958a285a866443 Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Tue, 7 Dec 2021 13:54:49 -0800 Subject: [PATCH 30/33] use single-argument form for interface assertion --- vault/core.go | 7 ++++--- vault/testing.go | 1 - 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/vault/core.go b/vault/core.go index d6da3656664a..aa1009c23382 100644 --- a/vault/core.go +++ b/vault/core.go @@ -3004,7 +3004,7 @@ func (c *Core) LoadInFlightReqData() map[string]InFlightReqData { currentInFlightReqMap := make(map[string]InFlightReqData) c.inFlightReqData.InFlightReqMap.Range(func(key, value interface{}) bool { // there is only one writer to this map, so skip checking for errors - v, _ := value.(InFlightReqData) + v := value.(InFlightReqData) currentInFlightReqMap[key.(string)] = v return true }) @@ -3021,7 +3021,8 @@ func (c *Core) UpdateInFlightReqData(reqID, clientID string) { return } - reqData, _ := v.(InFlightReqData) + // there is only one writer to this map, so skip checking for errors + reqData := v.(InFlightReqData) reqData.ClientID = clientID c.inFlightReqData.InFlightReqMap.Store(reqID, reqData) } @@ -3036,7 +3037,7 @@ func (c *Core) LogCompletedRequests(reqID string, statusCode int) { } // there is only one writer to this map, so skip checking for errors - reqData, _ := v.(InFlightReqData) + reqData := v.(InFlightReqData) c.logger.Log(logLevel, "completed_request","client_id", reqData.ClientID, "client_address", reqData.ClientRemoteAddr, "status_code", statusCode, "request_path", reqData.ReqPath, "request_method", reqData.Method) } diff --git a/vault/testing.go b/vault/testing.go index 3a2f0ab8eeac..966fddf9e6ca 100644 --- a/vault/testing.go +++ b/vault/testing.go @@ -130,7 +130,6 @@ func TestCoreWithSeal(t testing.T, testSeal Seal, enableRaw bool) *Core { func TestCoreWithCustomResponseHeaderAndUI(t testing.T, CustomResponseHeaders map[string]map[string]string, enableUI bool) (*Core, [][]byte, string) { confRaw := &server.Config{ - LogRequestsLevel: "basic", SharedConfig: &configutil.SharedConfig{ Listeners: []*configutil.Listener{ { From 087fb0063a44507d48ec5d87d5e48aa32215bd30 Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Tue, 7 Dec 2021 15:18:52 -0800 Subject: [PATCH 31/33] adding doc for the new configuration paramter --- .../docs/configuration/log_requests_level.mdx | 31 +++++++++++++++++++ 1 file changed, 31 insertions(+) create mode 100644 website/content/docs/configuration/log_requests_level.mdx diff --git a/website/content/docs/configuration/log_requests_level.mdx b/website/content/docs/configuration/log_requests_level.mdx new file mode 100644 index 000000000000..879f7129e6a4 --- /dev/null +++ b/website/content/docs/configuration/log_requests_level.mdx @@ -0,0 +1,31 @@ +--- +layout: docs +page_title: Log Completed Requests - Configuration +description: |- + Vault can be configured to log completed requests. +--- + +# Log Completed Requests + +Vault can be configured to log completed requests using the `log_requests_level` configuration parameter. + +## Activating the Log Completed Requests + +By default, logging completed requests is disabled. To activate the requests logging, set the `log_requests_level` +configuration option in the Vault server configuration to the desired logging level. The acceptable logging levels are +`error`, `warn`, info`, `debug`, and `trace`. +If the vault server is already running, you can still configure the parameter in the Vault server configuration, +and then send an `SIGHUP` signal to the vault process. + +```hcl +log_requests_level = "trace" + +listener "tcp" { + # ... +} +``` + +## Deactivating the Log Completed Requests + +To deactivate logging completed requests, simply remove the `log_requests_level` +configuration parameter from the vault server configuration, and send a `SIGHUP` signal to the vault process. From 5ed569b7e1427159c94a8fe4cdebc97914b8bc43 Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Tue, 7 Dec 2021 15:25:47 -0800 Subject: [PATCH 32/33] adding the new doc to the nav data file --- .../{log_requests_level.mdx => log-requests-level.mdx} | 0 website/data/docs-nav-data.json | 4 ++++ 2 files changed, 4 insertions(+) rename website/content/docs/configuration/{log_requests_level.mdx => log-requests-level.mdx} (100%) diff --git a/website/content/docs/configuration/log_requests_level.mdx b/website/content/docs/configuration/log-requests-level.mdx similarity index 100% rename from website/content/docs/configuration/log_requests_level.mdx rename to website/content/docs/configuration/log-requests-level.mdx diff --git a/website/data/docs-nav-data.json b/website/data/docs-nav-data.json index 2c2a646bf32b..6c10103023a6 100644 --- a/website/data/docs-nav-data.json +++ b/website/data/docs-nav-data.json @@ -366,6 +366,10 @@ "title": "ui", "path": "configuration/ui" }, + { + "title": "Log Completed Requests", + "path": "configuration/log-requests-level" + }, { "title": "Entropy Augmentation ENT", "path": "configuration/entropy-augmentation" From 8c8e5d8e6be268ca2251467be0f7f4408062b24e Mon Sep 17 00:00:00 2001 From: hamid ghaf Date: Tue, 7 Dec 2021 15:34:25 -0800 Subject: [PATCH 33/33] minor fix --- website/content/docs/configuration/log-requests-level.mdx | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/website/content/docs/configuration/log-requests-level.mdx b/website/content/docs/configuration/log-requests-level.mdx index 879f7129e6a4..8e076ce32199 100644 --- a/website/content/docs/configuration/log-requests-level.mdx +++ b/website/content/docs/configuration/log-requests-level.mdx @@ -13,7 +13,7 @@ Vault can be configured to log completed requests using the `log_requests_level` By default, logging completed requests is disabled. To activate the requests logging, set the `log_requests_level` configuration option in the Vault server configuration to the desired logging level. The acceptable logging levels are -`error`, `warn`, info`, `debug`, and `trace`. +`error`, `warn`, `info`, `debug`, and `trace`. If the vault server is already running, you can still configure the parameter in the Vault server configuration, and then send an `SIGHUP` signal to the vault process.