Remove logger outside of WriteJSONKeys

[alexsapran]

What does this PR do?

This change is removing the creation of the logger object inside of the WriteJSONKeys method.

That method is executed for each event causing the logger to initialize objects for each event.

Additionally adding a benchmark that show the impact of the change, for a specific scenario.

goos: darwin
goarch: amd64
pkg: github.com/elastic/beats/v7/libbeat/common/jsontransform
cpu: Intel(R) Core(TM) i9-9980HK CPU @ 2.40GHz
                 │  base.out   │             logger.out             │
                 │   sec/op    │   sec/op     vs base               │
WriteJSONKeys-16   3.202µ ± 9%   2.589µ ± 3%  -19.13% (p=0.000 n=8)

                 │   base.out   │             logger.out              │
                 │     B/op     │     B/op      vs base               │
WriteJSONKeys-16   2.820Ki ± 0%   2.344Ki ± 0%  -16.90% (p=0.000 n=8)

                 │  base.out  │            logger.out             │
                 │ allocs/op  │ allocs/op   vs base               │
WriteJSONKeys-16   23.00 ± 0%   16.00 ± 0%  -30.43% (p=0.000 n=8)

Signed-off-by: Alexandros, Sapranidis alexandros@elastic.co

Why is it important?

Under certain conditions for Filebeat, but not only, but the logger was also consuming overall a lot of memory. That memory then had to be reclaimed by the GC, so reducing the logger memory, actually reduces the gc work.

Checklist

• My code follows the style guidelines of this project
• I have commented my code, particularly in hard-to-understand areas
• I have added tests that prove my fix is effective or that my feature works
  - [ ] I have added an entry in CHANGELOG.next.asciidoc or CHANGELOG-developer.next.asciidoc.

How to test this PR locally

1. Build and trigger filebeat to load from a file and at the end capture the heap pprof.
2. Observe the heap memory allocation for the logp.NewLogger

[botelastic]

This pull request doesn't have a Team:<team> label.

[mergify]

This pull request does not have a backport label.
If this is a bug or security fix, could you label this PR @alexsapran? 🙏.
For such, you'll need to label your PR with:

• The upcoming major version of the Elastic Stack
• The upcoming minor version of the Elastic Stack (if you're not pushing a breaking change)

To fixup this pull request, you need to add the backport labels for the needed
branches, such as:

• backport-v8./d.0 is the label to automatically backport to the 8./d branch. /d is the digit

[amitkanfer]

🚀

[elasticmachine]

💚 Build Succeeded

the below badges are clickable and redirect to their specific view in the CI or DOCS

Expand to view the summary

Build stats

• Start Time: 2023-07-12T09:52:08.596+0000

• Duration: 71 min 44 sec

Test stats 🧪

Test	Results
Failed	0
Passed	27511
Skipped	2029
Total	29540

💚 Flaky test report

Tests succeeded.

🤖 GitHub comments

Expand to view the GitHub comments

To re-run your PR in the CI, just comment with:

• /test : Re-trigger the build.

• /package : Generate the packages and run the E2E tests.

• /beats-tester : Run the installation tests with beats-tester.

• run elasticsearch-ci/docs : Re-trigger the docs validation. (use unformatted text in the comment!)

[andrewkroh]

Does this logger still work? This becomes an order of initialization problem. The logp package is not yet initialized at this point so you get a no-op logger returned.

[alexsapran]

When tested in the unit/benchmark tests, it was properly initialized.
I can move this into a func init() on this package or see if we propagate it as part of the function parameters from the caller.

[andrewkroh]

it was properly initialized.

It will be initialized, but I would argue not properly. Moving it to an init() will not fix the issue since that still happens before the logp package receives its configuration through logp.Configure(). The godoc for NewLogger calls this out:

// NewLogger returns a new Logger labeled with the name of the selector. This
// should never be used from any global contexts, otherwise you will receive a
// no-op Logger. This is because the logp package needs to be initialized first.

If you apply this diff and run the test again, nothing gets logged.

go test -v -run TestWriteJSONKeys

diff --git a/libbeat/common/jsontransform/jsonhelper.go b/libbeat/common/jsontransform/jsonhelper.go
index 935eac90a7..c1e9a5d05b 100644
--- a/libbeat/common/jsontransform/jsonhelper.go
+++ b/libbeat/common/jsontransform/jsonhelper.go
@@ -40,6 +40,7 @@ var (
 
 // WriteJSONKeys writes the json keys to the given event based on the overwriteKeys option and the addErrKey
 func WriteJSONKeys(event *beat.Event, keys map[string]interface{}, expandKeys, overwriteKeys, addErrKey bool) {
+	logger.Error("NEVER SHOWN")
 	if expandKeys {
 		if err := expandFields(keys); err != nil {
 			logger.Errorf("JSON: failed to expand fields: %s", err)
diff --git a/libbeat/common/jsontransform/jsonhelper_test.go b/libbeat/common/jsontransform/jsonhelper_test.go
index d45ca5c3a3..9f43c1dbb3 100644
--- a/libbeat/common/jsontransform/jsonhelper_test.go
+++ b/libbeat/common/jsontransform/jsonhelper_test.go
@@ -24,10 +24,13 @@ import (
 	"github.com/stretchr/testify/require"
 
 	"github.com/elastic/beats/v7/libbeat/beat"
+	"github.com/elastic/elastic-agent-libs/logp"
 	"github.com/elastic/elastic-agent-libs/mapstr"
 )
 
 func TestWriteJSONKeys(t *testing.T) {
+	logp.TestingSetup()
+
 	now := time.Now()
 	now = now.Round(time.Second)

---

Solutions

1. One solution would be to defer initialization of the logger until the time of first use. Like

var (
	pkgLogger         *logp.Logger
	pkgLoggerInitOnce sync.Once
)

func logger() *logp.Logger {
	pkgLoggerInitOnce.Do(func() {
		pkgLogger = logp.NewLogger("jsontransform")
	})
	return pkgLogger
}

func WriteJSONKeys(...) {
    logger().Errorf("JSON: failed to expand fields: %s", err)
}

2. Remove logging from this function. I kind of find it annoying that it does any logging. There is already error handling present and that is via the addErrKey feature. As a user, if I care about errors then I should be using addErrKey==true.
   
   This highlights another inefficiency. When addErrKey==false the code is always executing createJSONError(err.Error()) which then goes completely unused.

[alexsapran]

I would opt for the solution 2. It makes more sense to not require any logging inside that function and if we need to, we can log in the caller.

The createJSONError(err.Error()) aspect, I noticed as well, but I was not 100% sure the reasoning behind that so I was kind of reluctant to touch in this changeset.

[amitkanfer]

Let's also fix the redundant call to createJSONError if addErrKey is false
we can change SetErrorWithOption to receive a string and call createJSONError only if addErrKey is true. Behavior will stay the same.

There are more new changes to review.

[andrewkroh]

Suggested change

	_, _ = errorField.Put("data", data)
	errorField["data"] = data

[andrewkroh]

But upon closer inspection, I think we should not add these two fields into the error object because they are not part of ECS error. Perhaps find a way to incorporate them into the error.message?

[alexsapran]

I just tried to keep compatibility with the current working code from

https://github.com/elastic/beats/pull/35920/files#diff-cbf4d8fa4d091014e5fe2a57fac3fa48f8361400b3cb55c2cff307b0a544f6abL125-R125

If we need to change this, we might want to do it as a followup work outside of the work on this PR, WDYT?

[andrewkroh]

I agree. I missed that they were already present.

[jlind23]

@alexsapran could you please move this over the line? I would happy to make it land as soon as possible.