Detect event rejection by mapping conflicts in system tests

[jsoriano]

Tests should fail when events are rejected during system tests, at least in the cases of mapping conflicts, where the problem can be in the package.

In Kibana 8.12.0 there was a regression (fixed in elastic/kibana#175970) when installing the index templates that was producing ingestion failures at least in the Prometheus package. But this was not detected by system tests in the daily builds, see for example this one: https://buildkite.com/elastic/integrations/builds/8422

We should ensure that these cases can be detected by system tests and in CI.

[jsoriano]

There were recent changes in the error messages in elastic-agent: https://github.com/elastic/beats/blame/ac6e2230bcfe766f1bd5695a59aa7d55116098f7/libbeat/outputs/elasticsearch/client.go#L438

So maybe this was not captured by the regexes we have now:

elastic-package/internal/testrunner/runners/system/runner.go

Lines 76 to 99 in a75fd6f

	var (
	errorPatterns = []logsByContainer{
	logsByContainer{
	containerName: "elastic-agent",
	patterns: []logsRegexp{
	logsRegexp{
	includes: regexp.MustCompile("^Cannot index event publisher.Event"),
	excludes: []*regexp.Regexp{
	// this regex is excluded to ensure that logs coming from the `system` package installed by default are not taken into account
	regexp.MustCompile(`action \[indices:data\/write\/bulk\[s\]\] is unauthorized for API key id \[.*\] of user \[.*\] on indices \[.*\], this action is granted by the index privileges \[.*\]`),
	},
	},
	logsRegexp{
	includes: regexp.MustCompile("->(FAILED|DEGRADED)"),
	// this regex is excluded to avoid a regresion in 8.11 that can make a component to pass to a degraded state during some seconds after reassigning or removing a policy
	excludes: []*regexp.Regexp{
	regexp.MustCompile(`Component state changed .* \(HEALTHY->DEGRADED\): Degraded: pid .* missed .* check-in`),
	},
	},
	},
	},
	}
	)

[mrodm]

Example log for system package:

{"log.level":"warn","@timestamp":"2024-02-06T11:41:29.172Z","message":"Cannot index event (status=403): dropping event! Enable debug logs to view the event and cause.","component":{"binary":"metricbeat","dataset":"elastic_agent.metricbeat","id":"system/metrics-default","type":"system/metrics"},"log":{"source":"system/metrics-default"},"log.logger":"elasticsearch","log.origin":{"file.line":450,"file.name":"elasticsearch/client.go","function":"github.com/elastic/beats/v7/libbeat/outputs/elasticsearch.(*Client).bulkCollectPublishFails"},"service.name":"metricbeat","ecs.version":"1.6.0","ecs.version":"1.6.0"}

Example log for prometheus package:

{"log.level":"warn","@timestamp":"2024-02-06T11:28:20.084Z","message":"Cannot index event (status=400): dropping event! Enable debug logs to view the event and cause.","component":{"binary":"metricbeat","dataset":"elastic_agent.metricbeat","id":"prometheus/metrics-default","type":"prometheus/metrics"},"log":{"source":"prometheus/metrics-default"},"log.origin":{"file.line":450,"file.name":"elasticsearch/client.go","function":"github.com/elastic/beats/v7/libbeat/outputs/elasticsearch.(*Client).bulkCollectPublishFails"},"service.name":"metricbeat","ecs.version":"1.6.0","log.logger":"elasticsearch","ecs.version":"1.6.0"}

Currently, elastic-package just checks the message field of the logs reported by docker-compose (elastic-agent)

As system errors should be skipped to keep the same behaviour

elastic-package/internal/testrunner/runners/system/runner.go

Line 84 in a75fd6f

// this regex is excluded to ensure that logs coming from the `system` package installed by default are not taken into account

It could be added a new field in this struct so it gets read

elastic-package/internal/stack/parselogs.go

Line 25 in a75fd6f

Message string `json:"message"`

and then add the required logic (and settings) here:

elastic-package/internal/testrunner/runners/system/runner.go

Line 1370 in a75fd6f

func (r *runner) anyErrorMessages(logsFilePath string, startTime time.Time, errorPatterns []logsRegexp) error {

Possible fields to be used form the log

 $ docker logs -f elastic-package-stack-elastic-agent-1 2>&1 | grep "Cannot index" | jq -r '.component.id'
prometheus/metrics-default
prometheus/metrics-default
prometheus/metrics-default
prometheus/metrics-default
system/metrics-default
system/metrics-default

 $ docker logs -f elastic-package-stack-elastic-agent-1 2>&1 | grep "Cannot index" | jq -r '.component.type'
prometheus/metrics
prometheus/metrics
prometheus/metrics
prometheus/metrics
system/metrics
system/metrics

 $ docker logs -f elastic-package-stack-elastic-agent-1 2>&1 | grep "Cannot index" | jq -r '.log.source'
prometheus/metrics-default
prometheus/metrics-default
prometheus/metrics-default
prometheus/metrics-default
system/metrics-default
system/metrics-default

[jsoriano]

Btw, another option might be to check if there are metrics that can give us an idea of events rejected. This would be more reliable than parsing logs.

[mrodm]

Another option is to set the log level of the agent to be "debug" and keep the same implementation (regex) to find the logs that would be considered errors

Implemented here this approach: #1660

Should we set that PR as closing this issue?

[jsoriano]

Another option is to set the log level of the agent to be "debug" and keep the same implementation (regex) to find the logs that would be considered errors

Implemented here this approach: #1660

Should we set that PR as closing this issue?

Yep, I think that we can close the issue after this. I think it would be good though to check also the metrics in case we can discover errors there. Metrics would be probably more reliable than parsing logs. But we can make this a different issue.