V2: Intermittent panic on output reload

[aleksmaus]

Intermittent panic on output reload, noticed during development during multiple agent starts.
Sometimes was getting the panic, details are below:

For confirmed bugs, please report:

• Version: V2 branch as if today (Sept 19th, 2022)
• Operating System: Mac OS X 12
• Steps to Reproduce:
  Start the agent. Once in awhile the panic happens.

Opening this tracker per @fearful-symmetry request.

panic: name batches already used

goroutine 79 [running]:
github.com/elastic/elastic-agent-libs/monitoring.panicErr(...)
	github.com/elastic/elastic-agent-libs@v0.2.11/monitoring/registry.go:257
github.com/elastic/elastic-agent-libs/monitoring.(*Registry).doAdd(0xc000191b5a?, {0x111054264?, 0x0?}, {0x11226ed78, 0xc0007315d0}, 0x10?)
	github.com/elastic/elastic-agent-libs@v0.2.11/monitoring/registry.go:159 +0x8d
github.com/elastic/elastic-agent-libs/monitoring.addVar(0xc0001107c0, {0x111054264, 0xe}, {0x0?, 0x11660cca8?, 0x30?}, {0x11226ed78, 0xc0007315d0}, {0x112277058, 0xc000b64650})
	github.com/elastic/elastic-agent-libs@v0.2.11/monitoring/metrics.go:227 +0x7d
github.com/elastic/elastic-agent-libs/monitoring.NewUint(0xc000b79c60?, {0x111054264, 0xe}, {0x0, 0x0, 0x0})
	github.com/elastic/elastic-agent-libs@v0.2.11/monitoring/metrics.go:79 +0xe5
github.com/elastic/beats/v7/libbeat/outputs.NewStats(0xc0001107c0?)
	github.com/elastic/beats/v7/libbeat/outputs/metrics.go:53 +0x46
github.com/elastic/beats/v7/libbeat/publisher/pipeline.loadOutput({0xc000110080?, 0xc000111500?, 0xc0002c58e0?, 0xc0005a8a80?}, 0xc000b79e00)
	github.com/elastic/beats/v7/libbeat/publisher/pipeline/module.go:144 +0x125
github.com/elastic/beats/v7/libbeat/publisher/pipeline.(*outputController).Reload(0xc000996000, 0xc000b644e0, 0xc000b644f0)
	github.com/elastic/beats/v7/libbeat/publisher/pipeline/controller.go:139 +0xfe
github.com/elastic/beats/v7/libbeat/cmd/instance.(*Beat).makeOutputReloader.func1(0xc000b79eb0?)
	github.com/elastic/beats/v7/libbeat/cmd/instance/beat.go:948 +0xac
github.com/elastic/beats/v7/libbeat/common/reload.ReloadableFunc.Reload(0xc000adfa20?, 0x1?)
	github.com/elastic/beats/v7/libbeat/common/reload/reload.go:192 +0x1f
github.com/elastic/beats/v7/x-pack/libbeat/management.(*BeatV2Manager).handleOutputReload(0xc000081200, 0xc000adfa20?)
	github.com/elastic/beats/v7/x-pack/libbeat/management/managerV2.go:338 +0x1d0
github.com/elastic/beats/v7/x-pack/libbeat/management.(*BeatV2Manager).handleUnitReload(0x10e7db6e6?, 0xc000adfa20)
	github.com/elastic/beats/v7/x-pack/libbeat/management/managerV2.go:313 +0x51
created by github.com/elastic/beats/v7/x-pack/libbeat/management.(*BeatV2Manager).unitListen
	github.com/elastic/beats/v7/x-pack/libbeat/management/managerV2.go:266 +0x4ca
panic: name type already used

goroutine 2242 [running]:
github.com/elastic/elastic-agent-libs/monitoring.panicErr(...)
	github.com/elastic/elastic-agent-libs@v0.2.11/monitoring/registry.go:257
github.com/elastic/elastic-agent-libs/monitoring.(*Registry).doAdd(0xc0001a1a68?, {0x1106d2af0?, 0x0?}, {0x11210eff8, 0xc000375860}, 0x10?)
	github.com/elastic/elastic-agent-libs@v0.2.11/monitoring/registry.go:159 +0x8d
github.com/elastic/elastic-agent-libs/monitoring.addVar(0xc0005baa80, {0x1106d2af0, 0x4}, {0x0?, 0x3?, 0xc00036fcd0?}, {0x11210eff8, 0xc000375860}, {0x112118938, 0xc00036fce0})
	github.com/elastic/elastic-agent-libs@v0.2.11/monitoring/metrics.go:227 +0x7d
github.com/elastic/elastic-agent-libs/monitoring.NewString(0x11216d0d8?, {0x1106d2af0, 0x4}, {0x0, 0x0, 0x0})
	github.com/elastic/elastic-agent-libs@v0.2.11/monitoring/metrics.go:172 +0xe5
github.com/elastic/beats/v7/libbeat/publisher/pipeline.loadOutput({0xc00011c080?, 0xc0006b7f00?, 0xc000ab1e90?, 0xc0002f4a80?}, 0xc00125be00?)
	github.com/elastic/beats/v7/libbeat/publisher/pipeline/module.go:153 +0x1e5
github.com/elastic/beats/v7/libbeat/publisher/pipeline.(*outputController).Reload(0xc000294200, 0xc00036efa0, 0xc00036efb0)
	github.com/elastic/beats/v7/libbeat/publisher/pipeline/controller.go:139 +0xfe
github.com/elastic/beats/v7/libbeat/cmd/instance.(*Beat).makeOutputReloader.func1(0xc00125beb0?)
	github.com/elastic/beats/v7/libbeat/cmd/instance/beat.go:948 +0xac
github.com/elastic/beats/v7/libbeat/common/reload.ReloadableFunc.Reload(0xc00057fc30?, 0x1?)
	github.com/elastic/beats/v7/libbeat/common/reload/reload.go:192 +0x1f
github.com/elastic/beats/v7/x-pack/libbeat/management.(*BeatV2Manager).handleOutputReload(0xc000081000, 0xc00057fc30?)
	github.com/elastic/beats/v7/x-pack/libbeat/management/managerV2.go:338 +0x1d0
github.com/elastic/beats/v7/x-pack/libbeat/management.(*BeatV2Manager).handleUnitReload(0x10cfca386?, 0xc00057fc30)
	github.com/elastic/beats/v7/x-pack/libbeat/management/managerV2.go:313 +0x51
created by github.com/elastic/beats/v7/x-pack/libbeat/management.(*BeatV2Manager).unitListen
	github.com/elastic/beats/v7/x-pack/libbeat/management/managerV2.go:266 +0x4ca
	```

[elasticmachine]

Pinging @elastic/elastic-agent-control-plane (Team:Elastic-Agent-Control-Plane)

[fearful-symmetry]

so, the fundamental problem is in loadOutput, which makes a bunch of calls like this:

monitoring.NewString(metrics, "type").Set(outName)

hence the panic: name type already used, as none of these values can be re-registered.

What I'm a tad confused about is why we're just seeing this now. Nothing in how we're calling the output reloader under v2 has changed; one theory I have is that the V1 controller was hard-restarting the beats under some circumstances, hence us hitting this now.

[andrewkroh]

one theory I have is that the V1 controller was hard-restarting the beats under some circumstances

Yeah, I think this was the case. The spec files contain ¹ restart_on_output_change: true.

Footnotes

1. https://github.com/elastic/elastic-agent/blob/7f5450b9843de1b5d9aa725faff2d5661735c162/internal/spec/filebeat.yml#L12 ↩