x-pack/filebeat/input/httpjson: improve template evaluation logging (e…

…lastic#36668) This adds valuable missing context to the debug logging emitted for template evaluation. Previously, only the final result was printed to the log, which failed to provide the information required to be able to determine why any given template was being executed. So add the target name to the logs.
Scholar-Li · Feb 5, 2024 · e5d78b7 · e5d78b7
1 parent 2eee678
commit e5d78b7
Show file tree

Hide file tree

Showing 7 changed files with 14 additions and 9 deletions.
diff --git a/CHANGELOG.next.asciidoc b/CHANGELOG.next.asciidoc
@@ -218,6 +218,7 @@ https://github.com/elastic/beats/compare/v8.8.1\...main[Check the HEAD diff]
 - Disable warning message about ingest pipeline loading when running under Elastic Agent. {pull}36659[36659]
 - Add input metrics to http_endpoint input. {issue}36402[36402] {pull}36427[36427]
 - Update mito CEL extension library to v1.6.0. {pull}36651[36651]
+- Improve template evaluation logging for HTTPJSON input. {pull}36668[36668]
 
 *Auditbeat*
 

diff --git a/x-pack/filebeat/input/httpjson/cursor.go b/x-pack/filebeat/input/httpjson/cursor.go
@@ -50,7 +50,7 @@ func (c *cursor) update(trCtx *transformContext) {
 	}
 
 	for k, cfg := range c.cfg {
-		v, _ := cfg.Value.Execute(trCtx, transformable{}, "", cfg.Default, c.log)
+		v, _ := cfg.Value.Execute(trCtx, transformable{}, k, cfg.Default, c.log)
 		if v != "" || !cfg.mustIgnoreEmptyValue() {
 			_, _ = c.state.Put(k, v)
 			c.log.Debugf("cursor.%s stored with %s", k, v)

diff --git a/x-pack/filebeat/input/httpjson/input_test.go b/x-pack/filebeat/input/httpjson/input_test.go
@@ -1248,6 +1248,8 @@ var testCases = []struct {
 }
 
 func TestInput(t *testing.T) {
+	logp.TestingSetup()
+
 	for _, test := range testCases {
 		t.Run(test.name, func(t *testing.T) {
 			if test.skipReason != "" {

diff --git a/x-pack/filebeat/input/httpjson/rate_limiter.go b/x-pack/filebeat/input/httpjson/rate_limiter.go
@@ -104,7 +104,7 @@ func (r *rateLimiter) getRateLimit(resp *http.Response) (int64, error) {
 	ctx := emptyTransformContext()
 	ctx.updateLastResponse(response{header: resp.Header.Clone()})
 
-	remaining, _ := r.remaining.Execute(ctx, tr, "", nil, r.log)
+	remaining, _ := r.remaining.Execute(ctx, tr, "rate-limit_remaining", nil, r.log)
 	if remaining == "" {
 		return 0, errors.New("remaining value is empty")
 	}
@@ -119,7 +119,7 @@ func (r *rateLimiter) getRateLimit(resp *http.Response) (int64, error) {
 	if r.earlyLimit != nil {
 		earlyLimit := *r.earlyLimit
 		if earlyLimit > 0 && earlyLimit < 1 {
-			limit, _ := r.limit.Execute(ctx, tr, "", nil, r.log)
+			limit, _ := r.limit.Execute(ctx, tr, "early_limit", nil, r.log)
 			if limit != "" {
 				l, err := strconv.ParseInt(limit, 10, 64)
 				if err == nil {
@@ -141,7 +141,7 @@ func (r *rateLimiter) getRateLimit(resp *http.Response) (int64, error) {
 		return 0, nil
 	}
 
-	reset, _ := r.reset.Execute(ctx, tr, "", nil, r.log)
+	reset, _ := r.reset.Execute(ctx, tr, "rate-limit_reset", nil, r.log)
 	if reset == "" {
 		return 0, errors.New("reset value is empty")
 	}

diff --git a/x-pack/filebeat/input/httpjson/request.go b/x-pack/filebeat/input/httpjson/request.go
@@ -385,7 +385,7 @@ func evaluateResponse(expression *valueTpl, data []byte, log *logp.Logger) (bool
 		lastResponse:  &response{body: dataMap},
 	}
 
-	val, err := expression.Execute(paramCtx, tr, "", nil, log)
+	val, err := expression.Execute(paramCtx, tr, "response_evaluation", nil, log)
 	if err != nil {
 		return false, fmt.Errorf("error while evaluating expression: %w", err)
 	}

diff --git a/x-pack/filebeat/input/httpjson/value_tpl.go b/x-pack/filebeat/input/httpjson/value_tpl.go
@@ -96,7 +96,7 @@ func (t *valueTpl) Unpack(in string) error {
 func (t *valueTpl) Execute(trCtx *transformContext, tr transformable, targetName string, defaultVal *valueTpl, log *logp.Logger) (val string, err error) {
 	fallback := func(err error) (string, error) {
 		if defaultVal != nil {
-			log.Debugf("template execution: falling back to default value")
+			log.Debugw("template execution: falling back to default value", "target", targetName)
 			return defaultVal.Execute(emptyTransformContext(), transformable{}, targetName, nil, log)
 		}
 		return "", err
@@ -107,7 +107,7 @@ func (t *valueTpl) Execute(trCtx *transformContext, tr transformable, targetName
 			val, err = fallback(errExecutingTemplate)
 		}
 		if err != nil {
-			log.Debugf("template execution failed: %v", err)
+			log.Debugw("template execution failed", "target", targetName, "error", err)
 		}
 		tryDebugTemplateValue(targetName, val, log)
 	}()
@@ -142,7 +142,7 @@ func tryDebugTemplateValue(target, val string, log *logp.Logger) {
 	case "Authorization", "Proxy-Authorization":
 		// ignore filtered headers
 	default:
-		log.Debugf("template execution: evaluated template %q", val)
+		log.Debugw("evaluated template", "target", target, "value", val)
 	}
 }
 

diff --git a/x-pack/filebeat/input/httpjson/value_tpl_test.go b/x-pack/filebeat/input/httpjson/value_tpl_test.go
@@ -19,6 +19,8 @@ import (
 )
 
 func TestValueTpl(t *testing.T) {
+	logp.TestingSetup()
+
 	cases := []struct {
 		name          string
 		value         string
@@ -764,7 +766,7 @@ func TestValueTpl(t *testing.T) {
 				assert.NoError(t, defTpl.Unpack(tc.paramDefVal))
 			}
 
-			got, err := tpl.Execute(tc.paramCtx, tc.paramTr, "", defTpl, logp.NewLogger(""))
+			got, err := tpl.Execute(tc.paramCtx, tc.paramTr, tc.name, defTpl, logp.NewLogger(""))
 			assert.Equal(t, tc.expectedVal, got)
 			if tc.expectedError == "" {
 				assert.NoError(t, err)