Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

Add the req_id attribute on the decision logs #5196

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

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions docs/content/management-decision-logs.md
Original file line number Diff line number Diff line change
Expand Up @@ -76,6 +76,7 @@ Decision log updates contain the following fields:
| `[_].erased` | `array[string]` | Set of JSON Pointers specifying fields in the event that were erased. |
| `[_].masked` | `array[string]` | Set of JSON Pointers specifying fields in the event that were masked. |
| `[_].nd_builtin_cache` | `object` | Key-value pairs of non-deterministic builtin names, paired with objects specifying the input/output mappings for each unique invocation of that builtin during policy evaluation. Intended for use in debugging and decision replay. Receivers will need to decode the JSON using Rego's JSON decoders. |
| `[_].req_id` | `number` | Incremental request identifier, and unique only to the OPA instance, for the request that started the policy query. The attribute value is the same as the value present in others logs (request, response, and print) and could be used to correlate them all. This attribute will be included just when OPA runtime is initialized in server mode and the log level is equal to or greater than info. |

If the decision log was successfully uploaded to the remote service, it should respond with an HTTP 2xx status. If the
service responds with a non-2xx status, OPA will requeue the last chunk containing decision log events and upload it
Expand Down
35 changes: 35 additions & 0 deletions logging/logging.go
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
package logging

import (
"context"
"io"

"github.com/sirupsen/logrus"
Expand Down Expand Up @@ -185,3 +186,37 @@ func (l *NoOpLogger) SetLevel(level Level) {
func (l *NoOpLogger) GetLevel() Level {
return l.level
}

type requestContextKey string

const reqCtxKey = requestContextKey("request-context-key")

// RequestContext represents the request context used to store data
// related to the request that could be used on logs.
type RequestContext struct {
ClientAddr string
ReqID uint64
ReqMethod string
ReqPath string
}

// Fields adapts the RequestContext fields to logrus.Fields.
func (rctx RequestContext) Fields() logrus.Fields {
return logrus.Fields{
"client_addr": rctx.ClientAddr,
"req_id": rctx.ReqID,
"req_method": rctx.ReqMethod,
"req_path": rctx.ReqPath,
}
}

// NewContext returns a copy of parent with an associated RequestContext.
func NewContext(parent context.Context, val *RequestContext) context.Context {
return context.WithValue(parent, reqCtxKey, val)
}

// FromContext returns the RequestContext associated with ctx, if any.
func FromContext(ctx context.Context) (*RequestContext, bool) {
requestContext, ok := ctx.Value(reqCtxKey).(*RequestContext)
return requestContext, ok
}
44 changes: 44 additions & 0 deletions logging/logging_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -82,3 +82,47 @@ func TestWithFieldsMerges(t *testing.T) {
t.Fatal("Logger did not contain configured field value")
}
}

func TestRequestContextFields(t *testing.T) {
fields := RequestContext{
ClientAddr: "127.0.0.1",
ReqID: 1,
ReqMethod: "GET",
ReqPath: "/test",
}.Fields()

var fieldvalue interface{}
var ok bool

if fieldvalue, ok = fields["client_addr"]; !ok {
t.Fatal("Fields did not contain the client_addr field")
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think we can use Error rather than Fatal for these assertions, no?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I used Fatal with the intention of following the structure of other tests, but I agree we can use Error and the test case run entirely.

}

if fieldvalue.(string) != "127.0.0.1" {
t.Fatal("Fields did not contain the configured client_addr value")
}

if fieldvalue, ok = fields["req_id"]; !ok {
t.Fatal("Fields did not contain the req_id field")
}

if fieldvalue.(uint64) != 1 {
t.Fatal("Fields did not contain the configured req_id value")
}

if fieldvalue, ok = fields["req_method"]; !ok {
t.Fatal("Fields did not contain the req_method field")
}

if fieldvalue.(string) != "GET" {
t.Fatal("Fields did not contain the configured req_method value")
}

if fieldvalue, ok = fields["req_path"]; !ok {
t.Fatal("Fields did not contain the req_path field")
}

if fieldvalue.(string) != "/test" {
t.Fatal("Fields did not contain the configured req_path value")
}
}
7 changes: 7 additions & 0 deletions plugins/logs/plugin.go
Original file line number Diff line number Diff line change
Expand Up @@ -61,6 +61,7 @@ type EventV1 struct {
RequestedBy string `json:"requested_by,omitempty"`
Timestamp time.Time `json:"timestamp"`
Metrics map[string]interface{} `json:"metrics,omitempty"`
RequestID uint64 `json:"req_id,omitempty"`

inputAST ast.Value
}
Expand Down Expand Up @@ -96,6 +97,7 @@ var errorKey = ast.StringTerm("error")
var requestedByKey = ast.StringTerm("requested_by")
var timestampKey = ast.StringTerm("timestamp")
var metricsKey = ast.StringTerm("metrics")
var requestIDKey = ast.StringTerm("req_id")

// AST returns the Rego AST representation for a given EventV1 object.
// This avoids having to round trip through JSON while applying a decision log
Expand Down Expand Up @@ -214,6 +216,10 @@ func (e *EventV1) AST() (ast.Value, error) {
event.Insert(metricsKey, ast.NewTerm(m))
}

if e.RequestID > 0 {
event.Insert(requestIDKey, ast.UIntNumberTerm(e.RequestID))
}

return event, nil
}

Expand Down Expand Up @@ -597,6 +603,7 @@ func (p *Plugin) Log(ctx context.Context, decision *server.Info) error {
NDBuiltinCache: decision.NDBuiltinCache,
RequestedBy: decision.RemoteAddr,
Timestamp: decision.Timestamp,
RequestID: decision.RequestID,
inputAST: decision.InputAST,
}

Expand Down
19 changes: 19 additions & 0 deletions plugins/logs/plugin_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -2266,6 +2266,25 @@ func TestEventV1ToAST(t *testing.T) {
NDBuiltinCache: &ndbCacheExample,
},
},
{
note: "event with req id",
event: EventV1{
Labels: map[string]string{"foo": "1", "bar": "2"},
DecisionID: "1234567890",
Bundles: map[string]BundleInfoV1{
"b1": {"revision7"},
"b2": {"0"},
"b3": {},
},
Input: &goInput,
Path: "/http/authz/allow",
RequestedBy: "[::1]:59943",
Result: &result,
Timestamp: time.Now(),
RequestID: 1,
inputAST: astInput,
},
},
}

for _, tc := range cases {
Expand Down
28 changes: 3 additions & 25 deletions runtime/logging.go
Original file line number Diff line number Diff line change
Expand Up @@ -6,7 +6,6 @@ package runtime

import (
"bytes"
"context"
"io"
"io/ioutil"
"net/http"
Expand All @@ -16,7 +15,6 @@ import (

"github.com/open-policy-agent/opa/logging"
"github.com/open-policy-agent/opa/topdown/print"
"github.com/sirupsen/logrus"
)

type loggingPrintHook struct {
Expand All @@ -26,7 +24,7 @@ type loggingPrintHook struct {
func (h loggingPrintHook) Print(pctx print.Context, msg string) error {
// NOTE(tsandall): if the request context is not present then do not panic,
// just log the print message without the additional context.
rctx, _ := pctx.Context.Value(reqCtxKey).(requestContext)
rctx, _ := logging.FromContext(pctx.Context)
fields := rctx.Fields()
fields["line"] = pctx.Location.String()
h.logger.WithFields(fields).Info(msg)
Expand Down Expand Up @@ -54,28 +52,8 @@ func (h *LoggingHandler) loggingEnabled(level logging.Level) bool {
return level <= h.logger.GetLevel()
}

type requestContextKey string

const reqCtxKey = requestContextKey("request-context-key")

type requestContext struct {
ClientAddr string
ReqID uint64
ReqMethod string
ReqPath string
}

func (rctx requestContext) Fields() logrus.Fields {
return logrus.Fields{
"client_addr": rctx.ClientAddr,
"req_id": rctx.ReqID,
"req_method": rctx.ReqMethod,
"req_path": rctx.ReqPath,
}
}

func (h *LoggingHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
var rctx requestContext
var rctx logging.RequestContext
rctx.ReqID = atomic.AddUint64(&h.requestID, uint64(1))
recorder := newRecorder(h.logger, w, r, rctx.ReqID, h.loggingEnabled(logging.Debug))
t0 := time.Now()
Expand All @@ -85,7 +63,7 @@ func (h *LoggingHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
rctx.ClientAddr = r.RemoteAddr
rctx.ReqMethod = r.Method
rctx.ReqPath = r.URL.EscapedPath()
r = r.WithContext(context.WithValue(r.Context(), reqCtxKey, rctx))
r = r.WithContext(logging.NewContext(r.Context(), &rctx))

var err error
fields := rctx.Fields()
Expand Down
1 change: 1 addition & 0 deletions server/buffer.go
Original file line number Diff line number Diff line change
Expand Up @@ -31,6 +31,7 @@ type Info struct {
Error error
Metrics metrics.Metrics
Trace []*topdown.Event
RequestID uint64
}

// BundleInfo contains information describing a bundle.
Expand Down
7 changes: 7 additions & 0 deletions server/server.go
Original file line number Diff line number Diff line change
Expand Up @@ -35,6 +35,7 @@ import (
"github.com/open-policy-agent/opa/ast"
"github.com/open-policy-agent/opa/bundle"
"github.com/open-policy-agent/opa/internal/json/patch"
"github.com/open-policy-agent/opa/logging"
"github.com/open-policy-agent/opa/metrics"
"github.com/open-policy-agent/opa/plugins"
bundlePlugin "github.com/open-policy-agent/opa/plugins/bundle"
Expand Down Expand Up @@ -2908,6 +2909,11 @@ func (l decisionLogger) Log(ctx context.Context, txn storage.Transaction, decisi
bundles[name] = BundleInfo{Revision: rev}
}

var reqID uint64
if rctx, ok := logging.FromContext(ctx); ok {
reqID = rctx.ReqID
}

info := &Info{
Txn: txn,
Revision: l.revision,
Expand All @@ -2922,6 +2928,7 @@ func (l decisionLogger) Log(ctx context.Context, txn storage.Transaction, decisi
Results: goResults,
Error: err,
Metrics: m,
RequestID: reqID,
}

if ndbCache != nil {
Expand Down