From 0685797c4a91f2d360545f4fb777eea0518bc4cb Mon Sep 17 00:00:00 2001 From: talip Date: Thu, 19 Oct 2023 14:49:59 +0530 Subject: [PATCH] add traceid and spanid to decision log. Signed-off-by: talip --- internal/internal.go | 10 ---- internal/internal_test.go | 32 ---------- .../distributedtracing_test.go | 58 +++++++++++++++++-- test/e2e/testing.go | 32 ++++++++++ 4 files changed, 85 insertions(+), 47 deletions(-) diff --git a/internal/internal.go b/internal/internal.go index aff08b344..ef75fb163 100644 --- a/internal/internal.go +++ b/internal/internal.go @@ -527,16 +527,6 @@ func (p *envoyExtAuthzGrpcServer) log(ctx context.Context, input interface{}, re info.SpanID = sctx.SpanID().String() } - p.manager.Logger().WithFields(map[string]interface{}{ - "query": p.cfg.parsedQuery.String(), - "dry-run": p.cfg.DryRun, - "decision": result.Decision, - "err": err, - "txn": result.TxnID, - "metrics": result.Metrics.All(), - "traceid": info.TraceID, - }).Error(" traceid should not work population in opa envoy.") - if result.NDBuiltinCache != nil { x, err := ast.JSON(result.NDBuiltinCache.AsValue()) if err != nil { diff --git a/internal/internal_test.go b/internal/internal_test.go index 82583712d..4e9b3bed8 100644 --- a/internal/internal_test.go +++ b/internal/internal_test.go @@ -167,38 +167,6 @@ func TestCheckAllow(t *testing.T) { } } -func TestCheckTraceIDInAllowedRequest(t *testing.T) { - // Example Envoy Check Request for input: - // curl --user bob:password -o /dev/null -s -w "%{http_code}\n" http://${GATEWAY_URL}/api/v1/products - - var req ext_authz.CheckRequest - if err := util.Unmarshal([]byte(exampleAllowedRequest), &req); err != nil { - panic(err) - } - - customLogger := &testPlugin{} - - server := testAuthzServer(nil, withCustomLogger(customLogger)) - ctx := context.Background() - output, err := server.Check(ctx, &req) - if err != nil { - t.Fatal(err) - } - event := customLogger.events[0] - - if output.Status.Code != int32(code.Code_OK) { - t.Fatal("Expected request to be allowed but got:", output) - } - - t.Log("Printing decision log event looking for traceid: ", event.TraceID) - t.Log("Printing decision log event looking for decisionid: ", event.DecisionID) - - if event.TraceID == "" { - t.Fatal("Expected TraceID to be present but got empty") - } - -} - func TestCheckTrigger(t *testing.T) { // Example Envoy Check Request for input: // curl --user bob:password -o /dev/null -s -w "%{http_code}\n" http://${GATEWAY_URL}/api/v1/products diff --git a/test/e2e/distributedtracing/distributedtracing_test.go b/test/e2e/distributedtracing/distributedtracing_test.go index 4e7fa0288..bea819e77 100644 --- a/test/e2e/distributedtracing/distributedtracing_test.go +++ b/test/e2e/distributedtracing/distributedtracing_test.go @@ -12,6 +12,7 @@ import ( ext_authz "github.com/envoyproxy/go-control-plane/envoy/service/auth/v3" "github.com/open-policy-agent/opa-envoy-plugin/test/e2e" + "github.com/open-policy-agent/opa/logging/test" "github.com/open-policy-agent/opa/plugins" "github.com/open-policy-agent/opa/tracing" "github.com/open-policy-agent/opa/util" @@ -24,6 +25,7 @@ import ( ) var spanExporter *tracetest.InMemoryExporter +var consoleLogger *test.Logger const exampleRequest = `{ "attributes": { @@ -70,6 +72,8 @@ func TestMain(m *testing.M) { tracing.RegisterHTTPTracing(&factory{}) spanExporter = tracetest.NewInMemoryExporter() tracerProvider := trace.NewTracerProvider(trace.WithSpanProcessor(trace.NewSimpleSpanProcessor(spanExporter))) + consoleLogger = test.New() + count := 0 countMutex := sync.Mutex{} ts := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { @@ -88,7 +92,7 @@ func TestMain(m *testing.M) { resp.body.count == 1 }` module := fmt.Sprintf(moduleFmt, ts.URL) - pluginsManager, err := e2e.TestAuthzServerWithWithOpts(module, "envoy/authz/allow", ":9191", plugins.WithTracerProvider(tracerProvider)) + pluginsManager, err := e2e.TestAuthzServerWithWithOpts(module, "envoy/authz/allow", ":9191", plugins.WithTracerProvider(tracerProvider), plugins.ConsoleLogger(consoleLogger)) if err != nil { log.Fatal(err) } @@ -98,10 +102,7 @@ func TestMain(m *testing.M) { os.Exit(m.Run()) } -// TestServerSpan exemplarily asserts that the server handlers emit OpenTelemetry spans -// with the correct attributes. It does NOT exercise all handlers, but contains one test -// with a GET and one with a POST. -func TestServerSpan(t *testing.T) { +func TestServerSpanAndTraceIdInDecisionLog(t *testing.T) { spanExporter.Reset() t.Run("envoy.service.auth.v3.Authorization Check", func(t *testing.T) { @@ -147,5 +148,52 @@ func TestServerSpan(t *testing.T) { if got, expected := spans[0].Parent.SpanID(), parentSpanID; got != expected { t.Errorf("expected span to be child of %v, got parent %v", expected, got) } + + var entry test.LogEntry + var found bool + + for _, entry = range consoleLogger.Entries() { + //t.Log(entry.Message) + if entry.Message == "Decision Log" { + found = true + } + } + + if !found { + t.Fatalf("Did not find 'Decision Log' event in captured log entries") + } + // Check for some important fields + expectedFields := map[string]*struct { + found bool + match func(*testing.T, string) + }{ + "labels": {}, + "decision_id": {}, + "trace_id": {}, + "span_id": {}, + "result": {}, + "timestamp": {}, + "type": {match: func(t *testing.T, actual string) { + if actual != "openpolicyagent.org/decision_logs" { + t.Fatalf("Expected field 'type' to be 'openpolicyagent.org/decision_logs'") + } + }}, + } + + // Ensure expected fields exist + for fieldName, rawField := range entry.Fields { + if fd, ok := expectedFields[fieldName]; ok { + if fieldValue, ok := rawField.(string); ok && fd.match != nil { + fd.match(t, fieldValue) + } + fd.found = true + } + } + + for field, fd := range expectedFields { + if !fd.found { + t.Errorf("Missing expected field in decision log: %s\n\nEntry: %+v\n\n", field, entry) + } + } }) } diff --git a/test/e2e/testing.go b/test/e2e/testing.go index 166a84e6c..a2b6f19a2 100644 --- a/test/e2e/testing.go +++ b/test/e2e/testing.go @@ -8,10 +8,30 @@ import ( "github.com/open-policy-agent/opa-envoy-plugin/internal" "github.com/open-policy-agent/opa-envoy-plugin/plugin" "github.com/open-policy-agent/opa/plugins" + "github.com/open-policy-agent/opa/plugins/logs" "github.com/open-policy-agent/opa/storage" "github.com/open-policy-agent/opa/storage/inmem" ) +type testPlugin struct { + events []logs.EventV1 +} + +func (*testPlugin) Start(context.Context) error { + return nil +} + +func (*testPlugin) Stop(context.Context) { +} + +func (*testPlugin) Reconfigure(context.Context, interface{}) { +} + +func (p *testPlugin) Log(_ context.Context, event logs.EventV1) error { + p.events = append(p.events, event) + return nil +} + // TestAuthzServerWithWithOpts creates a new AuthzServer // that implements the Envoy ext_authz API. Options for // plugins.Manager can/should be customized for the test case. @@ -37,6 +57,18 @@ func TestAuthzServerWithWithOpts(module string, path string, addr string, opts . return nil, err } m.Register(plugin.PluginName, internal.New(m, cfg)) + + m.Register("test_plugin", &testPlugin{}) + config, err := logs.ParseConfig([]byte(`{"plugin": "test_plugin"}`), nil, []string{"test_plugin"}) + + if err != nil { + return nil, err + } + config.ConsoleLogs = true + + logPlugin := logs.New(config, m) + m.Register(logs.Name, logPlugin) + if err := m.Start(ctx); err != nil { return nil, err }