diff --git a/logging/logging.go b/logging/logging.go index c08bc55d30..3ce76da468 100644 --- a/logging/logging.go +++ b/logging/logging.go @@ -220,3 +220,14 @@ func FromContext(ctx context.Context) (*RequestContext, bool) { requestContext, ok := ctx.Value(reqCtxKey).(*RequestContext) return requestContext, ok } + +const decisionCtxKey = requestContextKey("decision_id") + +func WithDecisionID(parent context.Context, id string) context.Context { + return context.WithValue(parent, decisionCtxKey, id) +} + +func DecisionIDFromContext(ctx context.Context) (string, bool) { + s, ok := ctx.Value(decisionCtxKey).(string) + return s, ok +} diff --git a/logging/logging_test.go b/logging/logging_test.go index 118da45b72..2c1aaa027f 100644 --- a/logging/logging_test.go +++ b/logging/logging_test.go @@ -2,8 +2,12 @@ package logging import ( "bytes" + "context" + "crypto/rand" "strings" "testing" + + "github.com/open-policy-agent/opa/internal/uuid" ) func TestWithFields(t *testing.T) { @@ -126,3 +130,19 @@ func TestRequestContextFields(t *testing.T) { t.Fatal("Fields did not contain the configured req_path value") } } + +func TestDecsionIDFromContext(t *testing.T) { + id, err := uuid.New(rand.Reader) + if err != nil { + t.Fatal(err) + } + ctx := WithDecisionID(context.Background(), id) + + act, ok := DecisionIDFromContext(ctx) + if !ok { + t.Fatalf("expected 'ok' to be true") + } + if exp := id; act != exp { + t.Errorf("Expected %q to be %q", act, exp) + } +} diff --git a/server/server.go b/server/server.go index 33ed045d20..4c6a88ef93 100644 --- a/server/server.go +++ b/server/server.go @@ -760,7 +760,7 @@ func (s *Server) instrumentHandler(handler func(http.ResponseWriter, *http.Reque return httpHandler } -func (s *Server) execQuery(ctx context.Context, r *http.Request, br bundleRevisions, txn storage.Transaction, decisionID string, parsedQuery ast.Body, input ast.Value, m metrics.Metrics, explainMode types.ExplainModeV1, includeMetrics, includeInstrumentation, pretty bool) (results types.QueryResponseV1, err error) { +func (s *Server) execQuery(ctx context.Context, r *http.Request, br bundleRevisions, txn storage.Transaction, parsedQuery ast.Body, input ast.Value, m metrics.Metrics, explainMode types.ExplainModeV1, includeMetrics, includeInstrumentation, pretty bool) (results types.QueryResponseV1, err error) { logger := s.getDecisionLogger(br) @@ -811,7 +811,7 @@ func (s *Server) execQuery(ctx context.Context, r *http.Request, br bundleRevisi output, err := rego.Eval(ctx) if err != nil { - _ = logger.Log(ctx, txn, decisionID, r.RemoteAddr, "", parsedQuery.String(), rawInput, input, nil, ndbCache, err, m) + _ = logger.Log(ctx, txn, "", parsedQuery.String(), rawInput, input, nil, ndbCache, err, m) return results, err } @@ -828,7 +828,7 @@ func (s *Server) execQuery(ctx context.Context, r *http.Request, br bundleRevisi } var x interface{} = results.Result - err = logger.Log(ctx, txn, decisionID, r.RemoteAddr, "", parsedQuery.String(), rawInput, input, &x, ndbCache, nil, m) + err = logger.Log(ctx, txn, "", parsedQuery.String(), rawInput, input, &x, ndbCache, nil, m) return results, err } @@ -913,7 +913,7 @@ func (s *Server) v0QueryPath(w http.ResponseWriter, r *http.Request, urlPath str m.Timer(metrics.ServerHandler).Start() decisionID := s.generateDecisionID() - ctx := r.Context() + ctx := logging.WithDecisionID(r.Context(), decisionID) annotateSpan(ctx, decisionID) input, err := readInputV0(r) @@ -977,14 +977,14 @@ func (s *Server) v0QueryPath(w http.ResponseWriter, r *http.Request, urlPath str partial, strictBuiltinErrors, instrument := false, false, false rego, err := s.makeRego(ctx, partial, strictBuiltinErrors, txn, input, urlPath, m, instrument, nil, opts) if err != nil { - _ = logger.Log(ctx, txn, decisionID, r.RemoteAddr, urlPath, "", goInput, input, nil, ndbCache, err, m) + _ = logger.Log(ctx, txn, urlPath, "", goInput, input, nil, ndbCache, err, m) writer.ErrorAuto(w, err) return } pq, err := rego.PrepareForEval(ctx) if err != nil { - _ = logger.Log(ctx, txn, decisionID, r.RemoteAddr, urlPath, "", goInput, input, nil, ndbCache, err, m) + _ = logger.Log(ctx, txn, urlPath, "", goInput, input, nil, ndbCache, err, m) writer.ErrorAuto(w, err) return } @@ -1009,7 +1009,7 @@ func (s *Server) v0QueryPath(w http.ResponseWriter, r *http.Request, urlPath str // Handle results. if err != nil { - _ = logger.Log(ctx, txn, decisionID, r.RemoteAddr, urlPath, "", goInput, input, nil, ndbCache, err, m) + _ = logger.Log(ctx, txn, urlPath, "", goInput, input, nil, ndbCache, err, m) writer.ErrorAuto(w, err) return } @@ -1022,7 +1022,7 @@ func (s *Server) v0QueryPath(w http.ResponseWriter, r *http.Request, urlPath str messageType = types.MsgFoundUndefinedError } err := types.NewErrorV1(types.CodeUndefinedDocument, fmt.Sprintf("%v: %v", messageType, ref)) - if logErr := logger.Log(ctx, txn, decisionID, r.RemoteAddr, urlPath, "", goInput, input, nil, ndbCache, err, m); logErr != nil { + if logErr := logger.Log(ctx, txn, urlPath, "", goInput, input, nil, ndbCache, err, m); logErr != nil { writer.ErrorAuto(w, logErr) return } @@ -1030,7 +1030,7 @@ func (s *Server) v0QueryPath(w http.ResponseWriter, r *http.Request, urlPath str writer.Error(w, http.StatusNotFound, err) return } - err = logger.Log(ctx, txn, decisionID, r.RemoteAddr, urlPath, "", goInput, input, &rs[0].Expressions[0].Value, ndbCache, nil, m) + err = logger.Log(ctx, txn, urlPath, "", goInput, input, &rs[0].Expressions[0].Value, ndbCache, nil, m) if err != nil { writer.ErrorAuto(w, err) return @@ -1321,7 +1321,7 @@ func (s *Server) v1DataGet(w http.ResponseWriter, r *http.Request) { m.Timer(metrics.ServerHandler).Start() decisionID := s.generateDecisionID() - ctx := r.Context() + ctx := logging.WithDecisionID(r.Context(), decisionID) annotateSpan(ctx, decisionID) vars := mux.Vars(r) @@ -1409,14 +1409,14 @@ func (s *Server) v1DataGet(w http.ResponseWriter, r *http.Request) { partial := false rego, err := s.makeRego(ctx, partial, strictBuiltinErrors, txn, input, urlPath, m, includeInstrumentation, buf, opts) if err != nil { - _ = logger.Log(ctx, txn, decisionID, r.RemoteAddr, urlPath, "", goInput, input, nil, ndbCache, err, m) + _ = logger.Log(ctx, txn, urlPath, "", goInput, input, nil, ndbCache, err, m) writer.ErrorAuto(w, err) return } pq, err := rego.PrepareForEval(ctx) if err != nil { - _ = logger.Log(ctx, txn, decisionID, r.RemoteAddr, urlPath, "", goInput, input, nil, ndbCache, err, m) + _ = logger.Log(ctx, txn, urlPath, "", goInput, input, nil, ndbCache, err, m) writer.ErrorAuto(w, err) return } @@ -1443,7 +1443,7 @@ func (s *Server) v1DataGet(w http.ResponseWriter, r *http.Request) { // Handle results. if err != nil { - _ = logger.Log(ctx, txn, decisionID, r.RemoteAddr, urlPath, "", goInput, input, nil, ndbCache, err, m) + _ = logger.Log(ctx, txn, urlPath, "", goInput, input, nil, ndbCache, err, m) writer.ErrorAuto(w, err) return } @@ -1468,7 +1468,7 @@ func (s *Server) v1DataGet(w http.ResponseWriter, r *http.Request) { return } } - err = logger.Log(ctx, txn, decisionID, r.RemoteAddr, urlPath, "", goInput, input, nil, ndbCache, nil, m) + err = logger.Log(ctx, txn, urlPath, "", goInput, input, nil, ndbCache, nil, m) if err != nil { writer.ErrorAuto(w, err) return @@ -1483,7 +1483,7 @@ func (s *Server) v1DataGet(w http.ResponseWriter, r *http.Request) { result.Explanation = s.getExplainResponse(explainMode, *buf, pretty) } - err = logger.Log(ctx, txn, decisionID, r.RemoteAddr, urlPath, "", goInput, input, result.Result, ndbCache, nil, m) + err = logger.Log(ctx, txn, urlPath, "", goInput, input, result.Result, ndbCache, nil, m) if err != nil { writer.ErrorAuto(w, err) return @@ -1561,7 +1561,7 @@ func (s *Server) v1DataPost(w http.ResponseWriter, r *http.Request) { m.Timer(metrics.ServerHandler).Start() decisionID := s.generateDecisionID() - ctx := r.Context() + ctx := logging.WithDecisionID(r.Context(), decisionID) annotateSpan(ctx, decisionID) vars := mux.Vars(r) @@ -1646,14 +1646,14 @@ func (s *Server) v1DataPost(w http.ResponseWriter, r *http.Request) { rego, err := s.makeRego(ctx, partial, strictBuiltinErrors, txn, input, urlPath, m, includeInstrumentation, buf, opts) if err != nil { - _ = logger.Log(ctx, txn, decisionID, r.RemoteAddr, urlPath, "", goInput, input, nil, ndbCache, err, m) + _ = logger.Log(ctx, txn, urlPath, "", goInput, input, nil, ndbCache, err, m) writer.ErrorAuto(w, err) return } pq, err := rego.PrepareForEval(ctx) if err != nil { - _ = logger.Log(ctx, txn, decisionID, r.RemoteAddr, urlPath, "", goInput, input, nil, ndbCache, err, m) + _ = logger.Log(ctx, txn, urlPath, "", goInput, input, nil, ndbCache, err, m) writer.ErrorAuto(w, err) return } @@ -1680,7 +1680,7 @@ func (s *Server) v1DataPost(w http.ResponseWriter, r *http.Request) { // Handle results. if err != nil { - _ = logger.Log(ctx, txn, decisionID, r.RemoteAddr, urlPath, "", goInput, input, nil, ndbCache, err, m) + _ = logger.Log(ctx, txn, urlPath, "", goInput, input, nil, ndbCache, err, m) writer.ErrorAuto(w, err) return } @@ -1709,7 +1709,7 @@ func (s *Server) v1DataPost(w http.ResponseWriter, r *http.Request) { return } } - err = logger.Log(ctx, txn, decisionID, r.RemoteAddr, urlPath, "", goInput, input, nil, ndbCache, nil, m) + err = logger.Log(ctx, txn, urlPath, "", goInput, input, nil, ndbCache, nil, m) if err != nil { writer.ErrorAuto(w, err) return @@ -1724,7 +1724,7 @@ func (s *Server) v1DataPost(w http.ResponseWriter, r *http.Request) { result.Explanation = s.getExplainResponse(explainMode, *buf, pretty) } - err = logger.Log(ctx, txn, decisionID, r.RemoteAddr, urlPath, "", goInput, input, result.Result, ndbCache, nil, m) + err = logger.Log(ctx, txn, urlPath, "", goInput, input, result.Result, ndbCache, nil, m) if err != nil { writer.ErrorAuto(w, err) return @@ -2142,7 +2142,7 @@ func (s *Server) v1QueryGet(w http.ResponseWriter, r *http.Request) { m := metrics.New() decisionID := s.generateDecisionID() - ctx := r.Context() + ctx := logging.WithDecisionID(r.Context(), decisionID) annotateSpan(ctx, decisionID) values := r.URL.Query() @@ -2186,7 +2186,7 @@ func (s *Server) v1QueryGet(w http.ResponseWriter, r *http.Request) { return } - results, err := s.execQuery(ctx, r, br, txn, decisionID, parsedQuery, nil, m, explainMode, includeMetrics, includeInstrumentation, pretty) + results, err := s.execQuery(ctx, r, br, txn, parsedQuery, nil, m, explainMode, includeMetrics, includeInstrumentation, pretty) if err != nil { switch err := err.(type) { case ast.Errors: @@ -2205,7 +2205,7 @@ func (s *Server) v1QueryPost(w http.ResponseWriter, r *http.Request) { m.Timer(metrics.ServerHandler).Start() decisionID := s.generateDecisionID() - ctx := r.Context() + ctx := logging.WithDecisionID(r.Context(), decisionID) annotateSpan(ctx, decisionID) var request types.QueryRequestV1 @@ -2257,7 +2257,7 @@ func (s *Server) v1QueryPost(w http.ResponseWriter, r *http.Request) { return } - results, err := s.execQuery(ctx, r, br, txn, decisionID, parsedQuery, input, m, explainMode, includeMetrics, includeInstrumentation, pretty) + results, err := s.execQuery(ctx, r, br, txn, parsedQuery, input, m, explainMode, includeMetrics, includeInstrumentation, pretty) if err != nil { switch err := err.(type) { case ast.Errors: @@ -2914,17 +2914,18 @@ type decisionLogger struct { logger func(context.Context, *Info) error } -func (l decisionLogger) Log(ctx context.Context, txn storage.Transaction, decisionID, remoteAddr, path string, query string, goInput *interface{}, astInput ast.Value, goResults *interface{}, ndbCache builtins.NDBCache, err error, m metrics.Metrics) error { +func (l decisionLogger) Log(ctx context.Context, txn storage.Transaction, path string, query string, goInput *interface{}, astInput ast.Value, goResults *interface{}, ndbCache builtins.NDBCache, err error, m metrics.Metrics) error { bundles := map[string]BundleInfo{} for name, rev := range l.revisions { bundles[name] = BundleInfo{Revision: rev} } - var reqID uint64 - if rctx, ok := logging.FromContext(ctx); ok { - reqID = rctx.ReqID + rctx := logging.RequestContext{} + if r, ok := logging.FromContext(ctx); ok { + rctx = *r } + decisionID, _ := logging.DecisionIDFromContext(ctx) info := &Info{ Txn: txn, @@ -2932,7 +2933,7 @@ func (l decisionLogger) Log(ctx context.Context, txn storage.Transaction, decisi Bundles: bundles, Timestamp: time.Now().UTC(), DecisionID: decisionID, - RemoteAddr: remoteAddr, + RemoteAddr: rctx.ClientAddr, Path: path, Query: query, Input: goInput, @@ -2940,7 +2941,7 @@ func (l decisionLogger) Log(ctx context.Context, txn storage.Transaction, decisi Results: goResults, Error: err, Metrics: m, - RequestID: reqID, + RequestID: rctx.ReqID, } if ndbCache != nil {