Always include HTTP request context in incoming req context

Previously the HTTP request context was included in the
request context at the info access log level. This means
if the access log level was set to error for instance,
the context would not include the http request context and
hence it would not be surfaced via decision logs.

This change always add the http request context to the request
context so that HTTP info like headers will be surfaced via decision
logs irrespective of the access log level.

Fixes: #6951

Signed-off-by: Ashutosh Narkar <[email protected]>

logging/logging.go

@@ -243,6 +243,17 @@ func FromContext(ctx context.Context) (*RequestContext, bool) {
 	return requestContext, ok
 }
 
+const httpReqCtxKey = requestContextKey("http-request-context-key")
+
+func WithHTTPRequestContext(parent context.Context, val *HTTPRequestContext) context.Context {
+	return context.WithValue(parent, httpReqCtxKey, val)
+}
+
+func HTTPRequestContextFromContext(ctx context.Context) (*HTTPRequestContext, bool) {
+	requestContext, ok := ctx.Value(httpReqCtxKey).(*HTTPRequestContext)
+	return requestContext, ok
+}
+
 const decisionCtxKey = requestContextKey("decision_id")
 
 func WithDecisionID(parent context.Context, id string) context.Context {

runtime/logging.go

@@ -58,9 +58,15 @@ func (h *LoggingHandler) loggingEnabled(level logging.Level) bool {
 }
 
 func (h *LoggingHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
+
+	cloneHeaders := r.Header.Clone()
+
+	// set the HTTP headers via a dedicated key on the parent context irrespective of logging level
+	r = r.WithContext(logging.WithHTTPRequestContext(r.Context(), &logging.HTTPRequestContext{Header: cloneHeaders}))
+
 	var rctx logging.RequestContext
 	rctx.ReqID = atomic.AddUint64(&h.requestID, uint64(1))
-	rctx.HTTPRequestContext = logging.HTTPRequestContext{Header: r.Header.Clone()}
+
 	recorder := newRecorder(h.logger, w, r, rctx.ReqID, h.loggingEnabled(logging.Debug))
 	t0 := time.Now()
 

runtime/logging_test.go

@@ -14,11 +14,13 @@ import (
 	"net/http"
 	"net/http/httptest"
 	"net/url"
+	"reflect"
 	"strings"
 	"testing"
 
 	"github.com/open-policy-agent/opa/logging"
 	"github.com/open-policy-agent/opa/logging/test"
+	"github.com/open-policy-agent/opa/server"
 )
 
 func TestValidateGzipHeader(t *testing.T) {
@@ -99,6 +101,68 @@ func TestValidateMetricsUrl(t *testing.T) {
 	}
 }
 
+func TestRequestErrorLoggingWithHTTPRequestContext(t *testing.T) {
+	ctx, cancel := context.WithCancel(context.Background())
+	t.Cleanup(cancel)
+
+	logger := test.New()
+	logger.SetLevel(logging.Error)
+
+	params := NewParams()
+	params.Addrs = &[]string{"localhost:0"}
+	params.Logger = logger
+
+	rt, err := NewRuntime(ctx, params)
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	initChannel := rt.Manager.ServerInitializedChannel()
+	go func() {
+		if err := rt.Serve(ctx); err != nil {
+			t.Error(err)
+		}
+	}()
+	<-initChannel
+
+	rec := httptest.NewRecorder()
+	req, err := http.NewRequest("GET", "/v1/data", nil)
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	req.Header.Set("foo", "bar")
+	req.Header.Set("foo2", "bar2")
+	req.Header.Add("foo2", "bar3")
+
+	decisions := []*server.Info{}
+
+	rt.server.WithDecisionLoggerWithErr(func(_ context.Context, info *server.Info) error {
+		decisions = append(decisions, info)
+		return nil
+	})
+
+	rt.server.Handler.ServeHTTP(rec, req)
+	if exp, act := http.StatusOK, rec.Result().StatusCode; exp != act {
+		t.Errorf("%s %s: expected HTTP %d, got %d", "GET", "/v1/data", exp, act)
+	}
+
+	if len(decisions) != 1 {
+		t.Fatalf("Expected exactly one decision but got: %d", len(decisions))
+	}
+
+	expHeaders := http.Header{}
+	expHeaders.Set("foo", "bar")
+	expHeaders.Add("foo2", "bar2")
+	expHeaders.Add("foo2", "bar3")
+
+	exp := logging.HTTPRequestContext{Header: expHeaders}
+
+	if !reflect.DeepEqual(decisions[0].HTTPRequestContext, exp) {
+		t.Fatalf("Expected HTTP request context %v but got: %v", exp, decisions[0].HTTPRequestContext)
+	}
+}
+
 func TestRequestLogging(t *testing.T) {
 	ctx, cancel := context.WithCancel(context.Background())
 	t.Cleanup(cancel)

server/server.go

@@ -2973,14 +2973,21 @@ func (l decisionLogger) Log(ctx context.Context, txn storage.Transaction, path s
 	}
 	decisionID, _ := logging.DecisionIDFromContext(ctx)
 
+	var httpRctx logging.HTTPRequestContext
+
+	httpRctxVal, _ := logging.HTTPRequestContextFromContext(ctx)
+	if httpRctxVal != nil {
+		httpRctx = *httpRctxVal
+	}
+
 	info := &Info{
 		Txn:                txn,
 		Revision:           l.revision,
 		Bundles:            bundles,
 		Timestamp:          time.Now().UTC(),
 		DecisionID:         decisionID,
 		RemoteAddr:         rctx.ClientAddr,
-		HTTPRequestContext: rctx.HTTPRequestContext,
+		HTTPRequestContext: httpRctx,
 		Path:               path,
 		Query:              query,
 		Input:              goInput,

server/server_test.go

@@ -3851,10 +3851,9 @@ func TestDecisionLoggingWithHTTPRequestContext(t *testing.T) {
 	req.Header.Set("foo2", "bar2")
 	req.Header.Add("foo2", "bar3")
 
-	var rctx logging.RequestContext
-	rctx.HTTPRequestContext = logging.HTTPRequestContext{Header: req.Header.Clone()}
+	httpRctx := logging.HTTPRequestContext{Header: req.Header.Clone()}
 
-	req = req.WithContext(logging.NewContext(req.Context(), &rctx))
+	req = req.WithContext(logging.WithHTTPRequestContext(req.Context(), &httpRctx))
 
 	if err := f.executeRequest(req, http.StatusOK, `{"decision_id": "1"}`); err != nil {
 		t.Fatal(err)