Add in-memory logger and use it on install and uninstall #4485

AndersonQ · 2024-03-27T08:01:14Z

What does this PR do?

It adds an in memory logger to the pkg/core/logger package and replaces the observer used during install and uninstall by the new in memory logger

Why is it important?

The zap observer isn't intended to be logged, it's an feature designed for tests and when printed without any processing it is just raw Go structs, making it hard to read and understand the logs.
Those logs are printed on install or uninstall failures, where the clarity of the logs are rather important for us or the user trying to understand what went wrong.

Checklist

My code follows the style guidelines of this project
I have commented my code, particularly in hard-to-understand areas
~~[ ] I have made corresponding changes to the documentation~~
~~[ ] I have made corresponding change to the default configuration files~~
~~[ ] I have added tests that prove my fix is effective or that my feature works~~
~~[ ] I have added an entry in ./changelog/fragments using the changelog tool~~
~~[ ] I have added an integration test or an E2E test~~

How to test this PR locally

run install with invalid flag values to force it to fail

Related issues

N/A

Logs

with the new in-memory logger:

root@elastic-agent:~# ./elastic-agent-8.14.0-SNAPSHOT-linux-x86_64/elastic-agent install -nf --url=https://REDACTED.elastic-cloud.com:443 --enrollment-token=Wrong_token
Installing in non-interactive mode.
[   =] Service Started  [1m41s] Elastic Agent successfully installed, starting enrollment.
[=== ] Waiting For Enroll...  [1m42s] {"log.level":"info","@timestamp":"2024-03-27T08:50:35.927+0100","log.origin":{"file.name":"cmd/enroll_cmd.go","file.line":530},"message":"Starting enrollment to URL: https://580c77ac20b347779aaa3c7a63a97827.fleet.us-west2.gcp.elastic-cloud.com:443/","ecs.version":"1.6.0"}
[=== ] Waiting For Enroll...  [1m42s] {"log.level":"info","@timestamp":"2024-03-27T08:50:36.804+0100","log.origin":{"file.name":"cmd/enroll_cmd.go","file.line":539},"message":"1st enrollment attempt failed, retrying for 10m0s, every 1m0s enrolling to URL: https://580c77ac20b347779aaa3c7a63a97827.fleet.us-west2.gcp.elastic-cloud.com:443/","ecs.version":"1.6.0"}
Error: fail to enroll: fail to execute request to fleet-server: status code: 401, fleet-server returned an error: ErrInvalidToken, message: token not valid utf8
For help, please see our troubleshooting guide at https://www.elastic.co/guide/en/fleet/8.14/fleet-troubleshooting.html
[ ===] Uninstalled  [1m44s] Error uninstalling. Printing logs
2024-03-27T07:48:58.882Z	DEBUG	[install]	Loaded configuration from /root/elastic-agent-8.14.0-SNAPSHOT-linux-x86_64/elastic-agent.yml
2024-03-27T07:48:58.882Z	DEBUG	[install]	Merged configuration from /root/elastic-agent-8.14.0-SNAPSHOT-linux-x86_64/elastic-agent.yml into result
2024-03-27T07:48:58.882Z	DEBUG	[install]	Merged all configuration files from [/root/elastic-agent-8.14.0-SNAPSHOT-linux-x86_64/elastic-agent.yml], no external input files
2024-03-27T07:48:58.882Z	DEBUG	[install.composable]	Starting controller for composable inputs
2024-03-27T07:48:58.882Z	DEBUG	[install.composable]	Started controller for composable inputs
2024-03-27T07:48:58.882Z	DEBUG	[install.composable]	Variable state changed for composable inputs; debounce started
2024-03-27T07:48:58.883Z	DEBUG	[install.composable]	Kubernetes leaderelection provider skipped, unable to connect: unable to build kube config due to error: invalid configuration: no configuration has been provided, try setting KUBERNETES_MASTER environment variable
2024-03-27T07:48:58.883Z	DEBUG	[install.composable.providers.kubernetes]	Kubernetes provider for resource pod skipped, unable to connect: unable to build kube config due to error: invalid configuration: no configuration has been provided, try setting KUBERNETES_MASTER environment variable
2024-03-27T07:48:58.883Z	DEBUG	[install.composable]	kubernetes_secrets provider skipped, unable to connect: unable to build kube config due to error: invalid configuration: no configuration has been provided, try setting KUBERNETES_MASTER environment variable
2024-03-27T07:48:58.883Z	DEBUG	[install.composable.providers.kubernetes]	Kubernetes provider for resource node skipped, unable to connect: unable to build kube config due to error: invalid configuration: no configuration has been provided, try setting KUBERNETES_MASTER environment variable
2024-03-27T07:48:58.894Z	DEBUG	[install.composable.providers.docker]	Start docker containers scanner
2024-03-27T07:48:58.894Z	DEBUG	[install.composable.providers.docker]	List containers
2024-03-27T07:48:58.895Z	DEBUG	[install.composable.providers.docker]	Fetching events since 2024-03-27 08:48:58.895535555 +0100 CET m=+5.211006626
2024-03-27T07:48:58.983Z	DEBUG	[install.composable]	Computing new variable state for composable inputs
2024-03-27T07:48:58.983Z	DEBUG	[install.composable.providers.docker]	Watcher stopped
2024-03-27T07:48:58.983Z	DEBUG	[install.composable]	Stopping controller for composable inputs
2024-03-27T07:48:59.084Z	DEBUG	[install.composable]	Stopped controller for composable inputs
2024-03-27T07:50:37.398Z	DEBUG	[install]	Loaded configuration from /root/elastic-agent-8.14.0-SNAPSHOT-linux-x86_64/elastic-agent.yml
2024-03-27T07:50:37.398Z	DEBUG	[install]	Merged configuration from /root/elastic-agent-8.14.0-SNAPSHOT-linux-x86_64/elastic-agent.yml into result
2024-03-27T07:50:37.398Z	DEBUG	[install]	Merged all configuration files from [/root/elastic-agent-8.14.0-SNAPSHOT-linux-x86_64/elastic-agent.yml], no external input files
2024-03-27T07:50:37.399Z	DEBUG	[install.composable]	Starting controller for composable inputs
2024-03-27T07:50:37.399Z	DEBUG	[install.composable]	Started controller for composable inputs
2024-03-27T07:50:37.399Z	DEBUG	[install.composable]	Variable state changed for composable inputs; debounce started
2024-03-27T07:50:37.399Z	DEBUG	[install.composable.providers.kubernetes]	Kubernetes provider for resource pod skipped, unable to connect: unable to build kube config due to error: invalid configuration: no configuration has been provided, try setting KUBERNETES_MASTER environment variable
2024-03-27T07:50:37.399Z	DEBUG	[install.composable.providers.kubernetes]	Kubernetes provider for resource node skipped, unable to connect: unable to build kube config due to error: invalid configuration: no configuration has been provided, try setting KUBERNETES_MASTER environment variable
2024-03-27T07:50:37.399Z	DEBUG	[install.composable]	kubernetes_secrets provider skipped, unable to connect: unable to build kube config due to error: invalid configuration: no configuration has been provided, try setting KUBERNETES_MASTER environment variable
2024-03-27T07:50:37.399Z	DEBUG	[install.composable]	Kubernetes leaderelection provider skipped, unable to connect: unable to build kube config due to error: invalid configuration: no configuration has been provided, try setting KUBERNETES_MASTER environment variable
2024-03-27T07:50:37.405Z	DEBUG	[install.composable.providers.docker]	Start docker containers scanner
2024-03-27T07:50:37.405Z	DEBUG	[install.composable.providers.docker]	List containers
2024-03-27T07:50:37.406Z	DEBUG	[install.composable.providers.docker]	Fetching events since 2024-03-27 08:50:37.406110265 +0100 CET m=+103.721581291
2024-03-27T07:50:37.499Z	DEBUG	[install.composable]	Computing new variable state for composable inputs
2024-03-27T07:50:37.499Z	DEBUG	[install.composable]	Stopping controller for composable inputs
2024-03-27T07:50:37.500Z	DEBUG	[install.composable.providers.docker]	Watcher stopped
2024-03-27T07:50:37.600Z	DEBUG	[install.composable]	Stopped controller for composable inputs
Error: enroll command failed for unknown reason: exit status 1
For help, please see our troubleshooting guide at https://www.elastic.co/guide/en/fleet/8.14/fleet-troubleshooting.html

how it's currently is:

root@elastic-agent:~# ./elastic-agent-8.12.2-linux-x86_64/elastic-agent  install -nf --url=https://580c77ac20b347779aaa3c7a63a97827.fleet.us-west2.gcp.elastic-cloud.com:443 --enrollment-token=REpuaGZvNEI4MmY0LUJCZzFySnM6TjZ2TEQ0bUFRN2lJSmRZOXo4TXFyUQ
Installing in non-interactive mode.
[   =] Service Started  [35s] Elastic Agent successfully installed, starting enrollment.
[==  ] Waiting For Enroll...  [36s] {"log.level":"info","@timestamp":"2024-03-27T08:53:39.751+0100","log.origin":{"file.name":"cmd/enroll_cmd.go","file.line":496},"message":"Starting enrollment to URL: https://580c77ac20b347779aaa3c7a63a97827.fleet.us-west2.gcp.elastic-cloud.com:443/","ecs.version":"1.6.0"}
[=   ] Waiting For Enroll...  [37s] {"log.level":"info","@timestamp":"2024-03-27T08:53:40.719+0100","log.origin":{"file.name":"cmd/enroll_cmd.go","file.line":505},"message":"1st enrollment attempt failed, retrying for 10m0s, every 1m0s enrolling to URL: https://580c77ac20b347779aaa3c7a63a97827.fleet.us-west2.gcp.elastic-cloud.com:443/","ecs.version":"1.6.0"}
Error: fail to enroll: fail to execute request to fleet-server: status code: 401, fleet-server returned an error: ErrInvalidToken, message: token not valid utf8
For help, please see our troubleshooting guide at https://www.elastic.co/guide/en/fleet/8.12/fleet-troubleshooting.html
[  ==] Uninstalled  [38s] Error uninstalling.  Printing logs
{debug 2024-03-27 08:53:40.957116065 +0100 CET m=+37.882332759 processes Error fetching PID info for 2, skipping: FillPidMetrics: error getting metadata for pid 2: error fetching exe from pid 2: readlink /proc/2/exe: no such file or directory github.com/elastic/elastic-agent-system-metrics@v0.9.1/metric/system/process/process.go:173 }
{debug 2024-03-27 08:53:40.957325274 +0100 CET m=+37.882541968 processes Error fetching PID info for 3, skipping: FillPidMetrics: error getting metadata for pid 3: error fetching exe from pid 3: readlink /proc/3/exe: no such file or directory github.com/elastic/elastic-agent-system-metrics@v0.9.1/metric/system/process/process.go:173 }

[...]

{debug 2024-03-27 08:53:40.972595852 +0100 CET m=+37.897812550 processes Error fetching PID info for 5582, skipping: FillPidMetrics: error getting metadata for pid 5582: error fetching exe from pid 5582: readlink /proc/5582/exe: no such file or directory github.com/elastic/elastic-agent-system-metrics@v0.9.1/metric/system/process/process.go:173 }
{debug 2024-03-27 08:53:40.987384521 +0100 CET m=+37.912601225  Loaded configuration from /root/elastic-agent-8.12.2-linux-x86_64/elastic-agent.yml github.com/elastic/elastic-agent/internal/pkg/config/loader.go:45 }
{debug 2024-03-27 08:53:40.987410892 +0100 CET m=+37.912627599  Merged configuration from /root/elastic-agent-8.12.2-linux-x86_64/elastic-agent.yml into result github.com/elastic/elastic-agent/internal/pkg/config/loader.go:57 }
{debug 2024-03-27 08:53:40.987427958 +0100 CET m=+37.912644664  Merged all configuration files from [/root/elastic-agent-8.12.2-linux-x86_64/elastic-agent.yml], no external input files github.com/elastic/elastic-agent/internal/pkg/config/loader.go:64 }
{debug 2024-03-27 08:53:40.987673866 +0100 CET m=+37.912890565 composable Starting controller for composable inputs github.com/elastic/elastic-agent/internal/pkg/composable/controller.go:112 }
{debug 2024-03-27 08:53:40.98769278 +0100 CET m=+37.912909486 composable Started controller for composable inputs github.com/elastic/elastic-agent/internal/pkg/composable/controller.go:155 }
{debug 2024-03-27 08:53:40.987734369 +0100 CET m=+37.912951054 composable Variable state changed for composable inputs; debounce started github.com/elastic/elastic-agent/internal/pkg/composable/controller.go:191 }
{debug 2024-03-27 08:53:40.988254504 +0100 CET m=+37.913471211 composable.providers.kubernetes Kubernetes provider for resource pod skipped, unable to connect: unable to build kube config due to error: invalid configuration: no configuration has been provided, try setting KUBERNETES_MASTER environment variable github.com/elastic/elastic-agent/internal/pkg/composable/providers/kubernetes/kubernetes.go:106 }
{debug 2024-03-27 08:53:40.988215108 +0100 CET m=+37.913431809 composable Kubernetes_secrets provider skipped, unable to connect: unable to build kube config due to error: invalid configuration: no configuration has been provided, try setting KUBERNETES_MASTER environment variable github.com/elastic/elastic-agent/internal/pkg/composable/providers/kubernetessecrets/kubernetes_secrets.go:97 }
{debug 2024-03-27 08:53:40.988262372 +0100 CET m=+37.913479079 composable Kubernetes leaderelection provider skipped, unable to connect: unable to build kube config due to error: invalid configuration: no configuration has been provided, try setting KUBERNETES_MASTER environment variable github.com/elastic/elastic-agent/internal/pkg/composable/providers/kubernetesleaderelection/kubernetes_leaderelection.go:53 }
{debug 2024-03-27 08:53:40.988525229 +0100 CET m=+37.913741942 composable.providers.kubernetes Kubernetes provider for resource node skipped, unable to connect: unable to build kube config due to error: invalid configuration: no configuration has been provided, try setting KUBERNETES_MASTER environment variable github.com/elastic/elastic-agent/internal/pkg/composable/providers/kubernetes/kubernetes.go:106 }
{debug 2024-03-27 08:53:40.988535588 +0100 CET m=+37.913752286 docker Docker client will negotiate the API version on the first request. github.com/elastic/elastic-agent-autodiscover@v0.6.6/docker/client.go:49 }
{debug 2024-03-27 08:53:40.995681656 +0100 CET m=+37.920898362 composable.providers.docker Start docker containers scanner github.com/elastic/elastic-agent-autodiscover@v0.6.6/docker/watcher.go:213 }
{debug 2024-03-27 08:53:40.995697137 +0100 CET m=+37.920913838 composable.providers.docker List containers github.com/elastic/elastic-agent-autodiscover@v0.6.6/docker/watcher.go:375 }
{debug 2024-03-27 08:53:40.996064703 +0100 CET m=+37.921281423 composable.providers.docker Fetching events since 2024-03-27 08:53:40.996020388 +0100 CET m=+37.921237078 github.com/elastic/elastic-agent-autodiscover@v0.6.6/docker/watcher.go:266 }
{debug 2024-03-27 08:53:41.088208428 +0100 CET m=+38.013425144 composable Computing new variable state for composable inputs github.com/elastic/elastic-agent/internal/pkg/composable/controller.go:207 }
{debug 2024-03-27 08:53:41.088364541 +0100 CET m=+38.013581227 composable Stopping controller for composable inputs github.com/elastic/elastic-agent/internal/pkg/composable/controller.go:159 }
{debug 2024-03-27 08:53:41.088415264 +0100 CET m=+38.013631997 composable.providers.docker Watcher stopped github.com/elastic/elastic-agent-autodiscover@v0.6.6/docker/watcher.go:313 }
{debug 2024-03-27 08:53:41.188806021 +0100 CET m=+38.114022705 composable Stopped controller for composable inputs github.com/elastic/elastic-agent/internal/pkg/composable/controller.go:188 }
Error: enroll command failed for unknown reason: exit status 1
For help, please see our troubleshooting guide at https://www.elastic.co/guide/en/fleet/8.12/fleet-troubleshooting.html

as a side note, the absence of the Error fetching PID are unrelated to this change. It was fixed by another PR.

Questions to ask yourself

How are we going to support this in production?
How are we going to measure its adoption?
How are we going to debug this?
What are the metrics I should take care of?
...

pchila

Code looks good, I just wish we would inject a configuration struct to instantate the logger rather than hardcoding values within logp.NewInMemory

pchila · 2024-03-27T08:10:21Z

pkg/core/logger/logger.go

+func NewInMemory(selector string) (*Logger, *bytes.Buffer) {
+	buff := bytes.Buffer{}
+
+	encoderConfig := ecszap.ECSCompatibleEncoderConfig(logp.ConsoleEncoderConfig())


Can we inject the logp.ConsoleEncoderConfig() configuration as parameter? Just in case this needs to be changed depending on the call location/ additional usages
Even better we could receive our log configuration, minus the output part

pchila · 2024-03-27T08:16:20Z

internal/pkg/agent/cmd/uninstall.go

-		for _, oLog := range oLogs {
-			fmt.Fprintf(os.Stderr, "%v\n", oLog.Entry)
-		}
+		fmt.Fprintf(os.Stderr, logBuff.String())


As per the static check this should be (same for install.go):

Suggested change

fmt.Fprintf(os.Stderr, logBuff.String())

fmt.Fprint(os.Stderr, logBuff.String())

elastic-sonarqube · 2024-03-27T09:01:28Z

Quality Gate passed

Kudos, no new issues were introduced!

0 New issues
0 Security Hotspots
77.8% 77.8% Coverage on New Code
0.0% 0.0% Duplication on New Code

See analysis details on SonarQube

leehinman · 2024-03-27T14:27:48Z

@AndersonQ would it be possible to migrate this to logp package? A cleaner in-memory logger could be useful in other places.

AndersonQ · 2024-04-02T06:04:31Z

@AndersonQ would it be possible to migrate this to logp package? A cleaner in-memory logger could be useful in other places.

done elastic/elastic-agent-libs#191

add in-memory logger and use it on install and uninstall

68fa840

AndersonQ added enhancement New feature or request backport-skip skip-changelog labels Mar 27, 2024

AndersonQ self-assigned this Mar 27, 2024

AndersonQ requested a review from a team as a code owner March 27, 2024 08:01

AndersonQ requested review from blakerouse and pchila March 27, 2024 08:01

pchila reviewed Mar 27, 2024

View reviewed changes

AndersonQ added 2 commits March 27, 2024 09:30

take in the encoder config as a parameter

73360e6

use Fprint instead of Fprintf

4b28129

pchila approved these changes Mar 27, 2024

View reviewed changes

AndersonQ enabled auto-merge (squash) March 27, 2024 12:16

AndersonQ merged commit 4cf1253 into elastic:main Mar 27, 2024
9 checks passed

AndersonQ deleted the in-memory-logger branch April 2, 2024 05:54

AndersonQ mentioned this pull request Apr 2, 2024

logp: add an in-memory logger elastic/elastic-agent-libs#191

Merged

2 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add in-memory logger and use it on install and uninstall #4485

Add in-memory logger and use it on install and uninstall #4485

AndersonQ commented Mar 27, 2024

pchila left a comment

pchila Mar 27, 2024

pchila Mar 27, 2024

elastic-sonarqube bot commented Mar 27, 2024

leehinman commented Mar 27, 2024

AndersonQ commented Apr 2, 2024

	fmt.Fprintf(os.Stderr, logBuff.String())
	fmt.Fprint(os.Stderr, logBuff.String())

Add in-memory logger and use it on install and uninstall #4485

Add in-memory logger and use it on install and uninstall #4485

Conversation

AndersonQ commented Mar 27, 2024

What does this PR do?

Why is it important?

Checklist

How to test this PR locally

Related issues

Logs

Questions to ask yourself

pchila left a comment

Choose a reason for hiding this comment

pchila Mar 27, 2024

Choose a reason for hiding this comment

pchila Mar 27, 2024

Choose a reason for hiding this comment

elastic-sonarqube bot commented Mar 27, 2024

Quality Gate passed

leehinman commented Mar 27, 2024

AndersonQ commented Apr 2, 2024