[Elastic Agent] Improve error logging (reduce to Info Level where possible) wrt changing logging level to debug

[ruflin]

• Version: 7.13.0-SNAPSHOT
• Environment: Docker

The Elastic Agent was running for a few minutes and I changed the logging level in the Fleet UI from Info to Debug. This all seems to have worked but the first we lines that were logged, looked as following:

2021-05-03T19:26:23.569Z	INFO	process/app.go:176	Signaling application to stop because of shutdown: metricbeat--7.13.0-SNAPSHOT
2021-05-03T19:26:24.066Z	INFO	log/reporter.go:40	2021-05-03T19:26:24Z - message: Application: filebeat--7.13.0-SNAPSHOT[4f12dd1d-f096-40b1-8bf4-8a0e66722775]: State changed to STOPPED: Stopped - type: 'STATE' - sub_type: 'STOPPED'
2021-05-03T19:26:24.066Z	INFO	log/reporter.go:40	2021-05-03T19:26:24Z - message: Application: filebeat--7.13.0-SNAPSHOT--36643631373035623733363936343635[4f12dd1d-f096-40b1-8bf4-8a0e66722775]: State changed to STOPPED: Stopped - type: 'STATE' - sub_type: 'STOPPED'
2021-05-03T19:26:24.066Z	INFO	log/reporter.go:40	2021-05-03T19:26:24Z - message: Application: metricbeat--7.13.0-SNAPSHOT--36643631373035623733363936343635[4f12dd1d-f096-40b1-8bf4-8a0e66722775]: State changed to STOPPED: Stopped - type: 'STATE' - sub_type: 'STOPPED'
2021-05-03T19:26:24.066Z	INFO	log/reporter.go:40	2021-05-03T19:26:24Z - message: Application: metricbeat--7.13.0-SNAPSHOT[4f12dd1d-f096-40b1-8bf4-8a0e66722775]: State changed to STOPPED: Stopped - type: 'STATE' - sub_type: 'STOPPED'
2021-05-03T19:26:24.999Z	ERROR	fleet/fleet_gateway.go:167	context canceled
2021-05-03T19:26:26.378Z	ERROR	fleet/fleet_gateway.go:167	context canceled
2021-05-03T19:26:27.852Z	INFO	fleet/fleet_gateway.go:298	Fleet gateway is stopping
2021-05-03T19:26:27.852Z	INFO	status/reporter.go:236	Elastic Agent status changed to: 'online'

I stumbled over the two ERROR log entries related to context which also contain very little "context" what it is about.

[elasticmachine]

Pinging @elastic/agent (Team:Agent)

[ruflin]

Maybe helpful, I found one more error in the logs in the Fleet UI:

21:26:23.566 [elastic_agent][error] failed to dispatch actions, error: acknowledge 0 actions '[]' for elastic-agent '4f12dd1d-f096-40b1-8bf4-8a0e66722775' failed: fail to ack to fleet: Post "http://fleet-server:8220/api/fleet/agents/4f12dd1d-f096-40b1-8bf4-8a0e66722775/acks?": context canceled

[dikshachauhan-qasource]

Hi @EricDavisX

While performing testing, we have observed above mentioned errors occurring on 7.13 Bc3 cloud qa build on changing agent logging level.

Screenshot1:

Further, Issue 25385 is also occurring on kibana UI. Logs start to generate as per changed logging level however not updated on agent details or logs page.

Screenshot 2:

Please let us know if anything else is required.

Thanks
QAS

[michalpristas]

i think this is expected, we change log level by reexecing and stopping all components. so context cancelled may be a byproduct of this workflow. log level is not a reloadable value

[ruflin]

If it is expected, should it be logged as error? And can we improve the log message?

[michalpristas]

what we discussed offline: this is expected from a point of view we log that context is cancelled and something is happening.
we dont have a check/signal to determine if this cancellation itself is expected or happened out of the blue.
this should be addressed and logged only if we're facing unintended behavior

[EricDavisX]

I'd consider the log line itself as a minor improvement - is there any discussion on why the log level in the UI wasn't updated (or wasn't updated quickly enough to be dismissed) ? I don't know how long we should wait before considering it a bug - thoughts from the technical perspective?

[ruflin]

@EricDavisX We didn't have any conversations around this but it is definitively worth discussing. @michalpristas Is the log level change also a new revision of the policy so it could be seen in the policy rollout overview? I assume not as it is specific per Agent. How can we let users know that it is rolled out? @EricDavisX I think we need to open an issue for this in Kibana to get the UX in place.

[EricDavisX]

Sounds good @ruflin. I logged this for the separate Kibana work: elastic/kibana#99788
and I updated the short desc here to be specific of improving the log level to not be an 'Error' if we can predict it is a known situation and is not actually severe.

This issue is more severe and will remain open for the fact that sometimes the log level just isn't updated:
elastic/beats#25385

[elasticmachine]

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

[jlind23]

As seen with @ph reducing the scope of this issue to rework only the status loop mentioned here:
https://user-images.githubusercontent.com/72375798/116995145-518c9780-acf7-11eb-9ad5-30b0db22a2e7.png

[jlind23]

@ph the status log is coming from this file:
https://github.com/elastic/elastic-agent/blob/main/internal/pkg/core/status/reporter.go#:~:text=%7D-,func%20(r%20*controller)%20updateStatus()%20%7B,%7D,-if%20r.status

I do not see any issues there. Is it possible that Kibana UI "fails" to parse our logs and retrieve all logs without taking care of the specified level?