diff --git a/CHANGELOG.md b/CHANGELOG.md index 0eb875ffb..3fe42b356 100644 --- a/CHANGELOG.md +++ b/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) diff --git a/config/request/context_key.go b/config/request/context_key.go index 0a311568f..a5b2023a5 100644 --- a/config/request/context_key.go +++ b/config/request/context_key.go @@ -22,7 +22,8 @@ const ( Error Handler LogCustomAccess - LogCustomUpstream + LogCustomUpstreamValue + LogCustomUpstreamError LogDebugLevel LogEntry OpenAPI diff --git a/eval/context.go b/eval/context.go index 89233ab55..4d518473e 100644 --- a/eval/context.go +++ b/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. diff --git a/eval/context_test.go b/eval/context_test.go index 2e4c1011a..e03749e6e 100644 --- a/eval/context_test.go +++ b/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 diff --git a/eval/http.go b/eval/http.go index 9d408c812..be05a59de 100644 --- a/eval/http.go +++ b/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 diff --git a/eval/lib/jwt_test.go b/eval/lib/jwt_test.go index 15acdf63a..19fa61d3b 100644 --- a/eval/lib/jwt_test.go +++ b/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}) diff --git a/handler/middleware/custom_logs.go b/handler/middleware/custom_logs.go index 8970978b7..01db2eeab 100644 --- a/handler/middleware/custom_logs.go +++ b/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) diff --git a/handler/transport/backend.go b/handler/transport/backend.go index 316a3fe1e..d0cb35760 100644 --- a/handler/transport/backend.go +++ b/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 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) diff --git a/logging/hooks/custom_logs.go b/logging/hooks/custom_logs.go index 5ec274bc7..12aca35fb 100644 --- a/logging/hooks/custom_logs.go +++ b/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 } diff --git a/logging/upstream_log.go b/logging/upstream_log.go index 95e180b40..19aa0a071 100644 --- a/logging/upstream_log.go +++ b/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 diff --git a/server/http_backend_test.go b/server/http_backend_test.go index 9cff16079..828bded79 100644 --- a/server/http_backend_test.go +++ b/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) + } + } +} diff --git a/server/testdata/integration/backends/08_couper.hcl b/server/testdata/integration/backends/08_couper.hcl new file mode 100644 index 000000000..539f87f62 --- /dev/null +++ b/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 + } + } +}