Fix custom logs (#658)

* fix: allow for more than 16 retries

* test: use backend variable in set_response_headers value

* fix: pass backend value to WithBeresp()

* test: use backend/backend_request/backend_response variables in custom_log_fields

* fix: evaluate backend custom_log_fields earlier

* reuse code

* not need to append to annother slice

* not need for backend variables when applying custom logs fields for access log

* changelog entry

* as there is only one log value or log error there is no need for slices

Co-authored-by: Alex Schneider <alex.schneider@avenga.com>

CHANGELOG.md

@@ -16,6 +16,9 @@ Unreleased changes are available as `avenga/couper:edge` container.
 * **Fixed**
   * Loop with evaluation error in [`custom_log_fields`](https://docs.couper.io/observation/logging#custom-logging) if log level is `"debug"` ([#659](https://github.com/avenga/couper/pull/659))
 
+* **Fixed**
+  * Use of [backend-related variables](https://docs.couper.io/configuration/variables#backend) in [`custom_log_fields`](https://docs.couper.io/observation/logging#custom-logging) within a [`backend` block](https://docs.couper.io/configuration/block/backend) ([#658](https://github.com/avenga/couper/pull/658))
+
 ---
 
 ## [1.11.1](https://github.com/avenga/couper/releases/tag/v1.11.1)

config/request/context_key.go

@@ -22,7 +22,8 @@ const (
 	Error
 	Handler
 	LogCustomAccess
-	LogCustomUpstream
+	LogCustomUpstreamValue
+	LogCustomUpstreamError
 	LogDebugLevel
 	LogEntry
 	OpenAPI

eval/context.go

@@ -189,7 +189,7 @@ func (c *Context) WithClientRequest(req *http.Request) *Context {
 	return ctx
 }
 
-func (c *Context) WithBeresp(beresp *http.Response, readBody bool) *Context {
+func (c *Context) WithBeresp(beresp *http.Response, backendVal cty.Value, readBody bool) *Context {
 	ctx := c.clone()
 	ctx.inner = context.WithValue(c.inner, request.ContextType, ctx)
 
@@ -203,6 +203,7 @@ func (c *Context) WithBeresp(beresp *http.Response, readBody bool) *Context {
 
 		ctx.eval.Variables[BackendRequest] = bereqVal
 		ctx.eval.Variables[BackendResponse] = berespVal
+		ctx.eval.Variables[Backend] = backendVal
 	}
 
 	// Prevent overriding existing variables with successive calls to this method.

eval/context_test.go

@@ -99,7 +99,7 @@ func TestNewHTTPContext(t *testing.T) {
 
 			helper.Must(eval.SetGetBody(req, eval.BufferRequest, 512))
 
-			ctx := baseCtx.WithClientRequest(req).WithBeresp(beresp, false).HCLContext()
+			ctx := baseCtx.WithClientRequest(req).WithBeresp(beresp, cty.NilVal, false).HCLContext()
 			ctx.Functions = nil // we are not interested in a functions test
 
 			var resultMap map[string]cty.Value

eval/http.go

@@ -333,6 +333,15 @@ var customLogFieldsSchema = &hcl.BodySchema{Attributes: []hcl.AttributeSchema{
 	{Name: attrCustomLogFields},
 }}
 
+func EvalCustomLogFields(httpCtx *hcl.EvalContext, body *hclsyntax.Body) (cty.Value, error) {
+	attr, ok := body.Attributes[attrCustomLogFields]
+	if !ok {
+		return cty.NilVal, nil
+	}
+
+	return Value(httpCtx, attr.Expr)
+}
+
 func ApplyCustomLogs(httpCtx *hcl.EvalContext, bodies []hcl.Body, logger *logrus.Entry) logrus.Fields {
 	var values []cty.Value
 

eval/lib/jwt_test.go

@@ -634,7 +634,7 @@ func TestJwtSignDynamic(t *testing.T) {
 
 			evalCtx := cf.Context.Value(request.ContextType).(*eval.Context).
 				WithClientRequest(req).
-				WithBeresp(beresp, false)
+				WithBeresp(beresp, cty.NilVal, false)
 
 			now := time.Now().Unix()
 			token, err := evalCtx.HCLContext().Functions[lib.FnJWTSign].Call([]cty.Value{cty.StringVal(tt.jspLabel), claims})

handler/middleware/custom_logs.go

@@ -27,9 +27,7 @@ func NewCustomLogsHandler(bodies []hcl.Body, next http.Handler, handlerName stri
 }
 
 func (c *CustomLogs) ServeHTTP(rw http.ResponseWriter, req *http.Request) {
-	var bodies []hcl.Body
-
-	ctx := context.WithValue(req.Context(), request.LogCustomAccess, append(bodies, c.bodies...))
+	ctx := context.WithValue(req.Context(), request.LogCustomAccess, c.bodies)
 	*req = *req.WithContext(ctx)
 
 	c.next.ServeHTTP(rw, req)

handler/transport/backend.go

@@ -126,10 +126,12 @@ func (b *Backend) RoundTrip(req *http.Request) (*http.Response, error) {
 		return nil, errors.BetaBackendTokenRequest.Label(b.name).With(err)
 	}
 
+	var backendVal cty.Value
 	hclCtx := eval.ContextFromRequest(req).HCLContextSync()
 	if v, ok := hclCtx.Variables[eval.Backends]; ok {
 		if m, exist := v.AsValueMap()[b.name]; exist {
 			hclCtx.Variables[eval.Backend] = m
+			backendVal = m
 		}
 	}
 
@@ -139,11 +141,6 @@ func (b *Backend) RoundTrip(req *http.Request) (*http.Response, error) {
 		}, err
 	}
 
-	logCh, _ := req.Context().Value(request.LogCustomUpstream).(chan hcl.Body)
-	if logCh != nil {
-		logCh <- ctxBody
-	}
-
 	// Execute before <b.evalTransport()> due to right
 	// handling of query-params in the URL attribute.
 	if err = eval.ApplyRequestContext(hclCtx, ctxBody, req); err != nil {
@@ -251,7 +248,16 @@ func (b *Backend) RoundTrip(req *http.Request) (*http.Response, error) {
 	evalCtx := eval.ContextFromRequest(req)
 	// has own body variable reference?
 	readBody := eval.MustBuffer(b.context)&eval.BufferResponse == eval.BufferResponse
-	evalCtx = evalCtx.WithBeresp(beresp, readBody)
+	evalCtx = evalCtx.WithBeresp(beresp, backendVal, readBody)
+
+	clfValue, err := eval.EvalCustomLogFields(evalCtx.HCLContext(), ctxBody)
+	if err != nil {
+		logError, _ := req.Context().Value(request.LogCustomUpstreamError).(*error)
+		*logError = err
+	} else if clfValue != cty.NilVal {
+		logValue, _ := req.Context().Value(request.LogCustomUpstreamValue).(*cty.Value)
+		*logValue = clfValue
+	}
 
 	err = eval.ApplyResponseContext(evalCtx.HCLContext(), ctxBody, beresp)
 

logging/hooks/custom_logs.go

@@ -3,10 +3,12 @@ package hooks
 import (
 	"github.com/hashicorp/hcl/v2"
 	"github.com/sirupsen/logrus"
+	"github.com/zclconf/go-cty/cty"
 
 	"github.com/avenga/couper/config/env"
 	"github.com/avenga/couper/config/request"
 	"github.com/avenga/couper/eval"
+	"github.com/avenga/couper/internal/seetie"
 	"github.com/avenga/couper/logging"
 )
 
@@ -76,72 +78,18 @@ func fireAccess(entry *logrus.Entry) {
 		return
 	}
 
-	ctx := syncedUpstreamContext(evalCtx, entry)
-
-	if fields := eval.ApplyCustomLogs(ctx, hclBodies, entry); len(fields) > 0 {
+	if fields := eval.ApplyCustomLogs(evalCtx.HCLContextSync(), hclBodies, entry); len(fields) > 0 {
 		entry.Data[customLogField] = fields
 	}
 }
 
 func fireUpstream(entry *logrus.Entry) {
-	evalCtx, ok := entry.Context.Value(request.ContextType).(*eval.Context)
-	if !ok {
+	logError, _ := entry.Context.Value(request.LogCustomUpstreamError).(*error)
+	if *logError != nil {
+		entry.Debug(*logError)
 		return
 	}
-	bodyCh, _ := entry.Context.Value(request.LogCustomUpstream).(chan hcl.Body)
-	if bodyCh == nil {
-		return
-	}
-
-	var bodies []hcl.Body
-	select {
-	case body := <-bodyCh:
-		bodies = append(bodies, body)
-	case <-entry.Context.Done():
-	}
-
-	ctx := syncedUpstreamContext(evalCtx, entry)
-
-	if fields := eval.ApplyCustomLogs(ctx, bodies, entry); len(fields) > 0 {
-		entry.Data[customLogField] = fields
-	}
-}
-
-// syncedUpstreamContext prepares the local backend variable.
-func syncedUpstreamContext(evalCtx *eval.Context, entry *logrus.Entry) *hcl.EvalContext {
-	ctx := evalCtx.HCLContextSync()
-
-	tr, _ := entry.Context.Value(request.TokenRequest).(string)
-	rtName, _ := entry.Context.Value(request.RoundTripName).(string)
-	isTr := tr != ""
-
-	if rtName == "" {
-		return ctx
-	}
-
-	if _, ok := ctx.Variables[eval.BackendRequests]; ok {
-		for k, v := range ctx.Variables[eval.BackendRequests].AsValueMap() {
-			if isTr && k == eval.TokenRequestPrefix+tr {
-				ctx.Variables[eval.BackendRequest] = v
-				break
-			} else if k == rtName {
-				ctx.Variables[eval.BackendRequest] = v
-				break
-			}
-		}
-	}
-
-	if _, ok := ctx.Variables[eval.BackendResponses]; ok {
-		for k, v := range ctx.Variables[eval.BackendResponses].AsValueMap() {
-			if isTr && k == eval.TokenRequestPrefix+tr {
-				ctx.Variables[eval.BackendResponse] = v
-				break
-			} else if k == rtName {
-				ctx.Variables[eval.BackendResponse] = v
-				break
-			}
-		}
-	}
-
-	return ctx
+	logValue, _ := entry.Context.Value(request.LogCustomUpstreamValue).(*cty.Value)
+	fields := seetie.ValueToLogFields(*logValue)
+	entry.Data[customLogField] = fields
 }

logging/upstream_log.go

@@ -20,7 +20,6 @@ import (
 	"github.com/avenga/couper/handler/validation"
 	"github.com/avenga/couper/internal/seetie"
 	"github.com/avenga/couper/utils"
-	"github.com/hashicorp/hcl/v2"
 )
 
 var (
@@ -82,10 +81,12 @@ func (u *UpstreamLog) RoundTrip(req *http.Request) (*http.Response, error) {
 
 	fields["request"] = requestFields
 
+	var logValue cty.Value
+	var logError error
 	berespBytes := int64(0)
-	logCtxCh := make(chan hcl.Body, 17) // TODO: Will block with oauth2 token retries >= 17
 	tokenRetries := uint8(0)
-	outctx := context.WithValue(req.Context(), request.LogCustomUpstream, logCtxCh)
+	outctx := context.WithValue(req.Context(), request.LogCustomUpstreamValue, &logValue)
+	outctx = context.WithValue(outctx, request.LogCustomUpstreamError, &logError)
 	outctx = context.WithValue(outctx, request.BackendBytes, &berespBytes)
 	outctx = context.WithValue(outctx, request.TokenRequestRetries, &tokenRetries)
 	oCtx, openAPIContext := validation.NewWithContext(outctx)
@@ -95,8 +96,6 @@ func (u *UpstreamLog) RoundTrip(req *http.Request) (*http.Response, error) {
 	beresp, err := u.next.RoundTrip(outreq)
 	rtDone := time.Now()
 
-	close(logCtxCh)
-
 	// FIXME: Can host be empty?
 	if outreq.Host != "" {
 		requestFields["origin"] = outreq.Host

server/http_backend_test.go

@@ -403,3 +403,82 @@ func TestBackend_Oauth2_TokenEndpoint(t *testing.T) {
 		t.Errorf("unexpected number of requests, want: %d, got: %d", retries+1, requestCount)
 	}
 }
+
+func TestBackend_BackendVar(t *testing.T) {
+	helper := test.New(t)
+	shutdown, hook := newCouper("testdata/integration/backends/08_couper.hcl", helper)
+	defer shutdown()
+
+	client := test.NewHTTPClient()
+
+	hook.Reset()
+
+	req, _ := http.NewRequest(http.MethodGet, "http://couper.dev:8080/anything", nil)
+	res, err := client.Do(req)
+	helper.Must(err)
+
+	hHealthy1 := res.Header.Get("x-healthy-1")
+	hHealthy2 := res.Header.Get("x-healthy-2")
+	if hHealthy1 != "true" {
+		t.Errorf("expected x-healthy-1 to be true, got %q", hHealthy1)
+	}
+	if hHealthy2 != "true" {
+		t.Errorf("expected x-healthy-2 to be true, got %q", hHealthy2)
+	}
+	hRequestPath1 := res.Header.Get("x-rp-1")
+	hRequestPath2 := res.Header.Get("x-rp-2")
+	if hRequestPath1 != "/anything" {
+		t.Errorf("expected x-rp-1 to be %q, got %q", "/anything", hRequestPath1)
+	}
+	if hRequestPath2 != "/anything" {
+		t.Errorf("expected x-rp-2 to be %q, got %q", "/anything", hRequestPath2)
+	}
+	hResponseStatus1 := res.Header.Get("x-rs-1")
+	hResponseStatus2 := res.Header.Get("x-rs-2")
+	if hResponseStatus1 != "200" {
+		t.Errorf("expected x-rs-1 to be %q, got %q", "/200", hResponseStatus1)
+	}
+	if hResponseStatus2 != "200" {
+		t.Errorf("expected x-rs-2 to be %q, got %q", "/200", hResponseStatus2)
+	}
+
+	for _, e := range hook.AllEntries() {
+		if e.Data["type"] != "couper_backend" {
+			continue
+		}
+		custom, _ := e.Data["custom"].(logrus.Fields)
+
+		if lHealthy1, ok := custom["healthy_1"].(bool); !ok {
+			t.Error("expected healthy_1 to be set and bool")
+		} else if lHealthy1 != true {
+			t.Errorf("expected healthy_1 to be true, got %v", lHealthy1)
+		}
+		if lHealthy2, ok := custom["healthy_2"].(bool); !ok {
+			t.Error("expected healthy_2 to be set and bool")
+		} else if lHealthy2 != true {
+			t.Errorf("expected healthy_2 to be true, got %v", lHealthy2)
+		}
+
+		if lRequestPath1, ok := custom["rp_1"].(string); !ok {
+			t.Error("expected rp_1 to be set and string")
+		} else if lRequestPath1 != "/anything" {
+			t.Errorf("expected rp_1 to be %q, got %v", "/anything", lRequestPath1)
+		}
+		if lRequestPath2, ok := custom["rp_2"].(string); !ok {
+			t.Error("expected rp_2 to be set and string")
+		} else if lRequestPath2 != "/anything" {
+			t.Errorf("expected rp_2 to be %q, got %v", "/anything", lRequestPath2)
+		}
+
+		if lResponseStatus1, ok := custom["rs_1"].(float64); !ok {
+			t.Error("expected rs_1 to be set and float64")
+		} else if lResponseStatus1 != 200 {
+			t.Errorf("expected rs_1 to be %d, got %v", 200, lResponseStatus1)
+		}
+		if lResponseStatus2, ok := custom["rs_2"].(float64); !ok {
+			t.Error("expected rs_2 to be set and float64")
+		} else if lResponseStatus2 != 200 {
+			t.Errorf("expected rs_2 to be %d, got %v", 200, lResponseStatus2)
+		}
+	}
+}

server/testdata/integration/backends/08_couper.hcl

@@ -0,0 +1,29 @@
+server {
+  endpoint "/**" {
+    proxy {
+      backend = "be"
+    }
+  }
+}
+
+definitions {
+  backend "be" {
+    origin = "${env.COUPER_TEST_BACKEND_ADDR}"
+    set_response_headers = {
+      x-healthy-1 = backend.health.healthy ? "true" : "false"
+      x-healthy-2 = backends.be.health.healthy ? "true" : "false"
+      x-rp-1 = backend_request.path
+      x-rp-2 = backend_requests.default.path
+      x-rs-1 = backend_response.status
+      x-rs-2 = backend_responses.default.status
+    }
+    custom_log_fields = {
+      healthy_1 = backend.health.healthy
+      healthy_2 = backends.be.health.healthy
+      rp_1 = backend_request.path
+      rp_2 = backend_requests.default.path
+      rs_1 = backend_response.status
+      rs_2 = backend_responses.default.status
+    }
+  }
+}