From 017b589ca3c87c54e0c41e0bd2d9bdaf0f22e6a4 Mon Sep 17 00:00:00 2001 From: Dan Kortschak <90160302+efd6@users.noreply.github.com> Date: Thu, 28 Sep 2023 19:50:00 +0930 Subject: [PATCH] x-pack/filebeat/input/httpjson: improve template evaluation logging (#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. --- CHANGELOG.next.asciidoc | 1 + x-pack/filebeat/input/httpjson/cursor.go | 2 +- x-pack/filebeat/input/httpjson/input_test.go | 2 ++ x-pack/filebeat/input/httpjson/rate_limiter.go | 6 +++--- x-pack/filebeat/input/httpjson/request.go | 2 +- x-pack/filebeat/input/httpjson/value_tpl.go | 6 +++--- x-pack/filebeat/input/httpjson/value_tpl_test.go | 4 +++- 7 files changed, 14 insertions(+), 9 deletions(-) diff --git a/CHANGELOG.next.asciidoc b/CHANGELOG.next.asciidoc index a8ed9f032c5f..2064650e19f3 100644 --- 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 index 92cd53a52a29..1a864361ee70 100644 --- 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 index e4d94527e725..de4cc3f11e69 100644 --- 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 index dcbed7c1ac91..30c50ae3f052 100644 --- 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 index f70ab4094dff..248918e81166 100644 --- 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 index 133271e726fe..97bc75a62d94 100644 --- 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 index 37589cd88218..487451099ad6 100644 --- 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)