Enabling debug logs with add_cloud_metadata introduces 3s startup delay

[mauri870]

If a Beat is running with debug level and the add_cloud_metadata processor, there is an additional 3s delay during initialization. This issue does not occur at higher logging levels. It's especially important for BeatsReceivers, since this 3s delay affects receiver creation time (e.g. factory.CreateLogs), slowing down the initialization of the entire OTel Collector.

Run filebeat in normal mode and then in debug mode with -d '*' with the following config:

filebeat.inputs:
  - type: benchmark
    enabled: true
    message: "test"
    count: 1
processors:
  - add_cloud_metadata: ~

path.data: "/tmp/data"
output.console:
  enabled: true

Another way to reproduce it is to modify BenchmarkFactory in fbreceiver to use debug logs:

diff --git a/x-pack/filebeat/fbreceiver/receiver_test.go b/x-pack/filebeat/fbreceiver/receiver_test.go
index 0a8eed99ec..417af2398b 100644
--- a/x-pack/filebeat/fbreceiver/receiver_test.go
+++ b/x-pack/filebeat/fbreceiver/receiver_test.go
@@ -92,7 +92,7 @@ func BenchmarkFactory(b *testing.B) {
                                "otelconsumer": map[string]interface{}{},
                        },
                        "logging": map[string]interface{}{
-                               "level": "info",
+                               "level": "debug",
                                "selectors": []string{
                                        "*",
                                },
@@ -105,7 +105,7 @@ func BenchmarkFactory(b *testing.B) {
        core := zapcore.NewCore(
                zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig()),
                zapcore.Lock(zapcore.AddSync(&zapLogs)),
-               zapcore.InfoLevel)
+               zapcore.DebugLevel)

        factory := NewFactory()

$ go test -bench=. -benchmem -run=^BenchmarkFactory$ ./x-pack/filebeat/fbreceiver

This results in a single benchmark iteration since it takes ~3s to run.

My investigation shows that delay occurs on the following line:

beats/libbeat/processors/processor.go

Line 113 in be14d14

procs.log.Debugf("Generated new processors: %v", procs)

It's not immediately clear why, but the formatter eventually calls fmt.Stringer on add_cloud_metadata:

beats/libbeat/processors/add_cloud_metadata/add_cloud_metadata.go

Lines 91 to 94 in be14d14

	func (r result) String() string {
	return fmt.Sprintf("result=[provider:%v, error=%v, metadata=%v]",
	r.provider, r.err, r.metadata)
	}

This, in turn, causes the processor to be initialized early:

beats/libbeat/processors/add_cloud_metadata/add_cloud_metadata.go

Lines 109 to 112 in be14d14

	func (p *addCloudMetadata) getMeta() mapstr.M {
	p.init()
	return p.metadata.Clone()
	}

Since this behavior doesn’t occur at other log levels and it affects Beat receivers component creation time, we should address it somehow.

[elasticmachine]

Pinging @elastic/elastic-agent-data-plane (Team:Elastic-Agent-Data-Plane)