[elastic-agent] Improve log messages (#25372) (#25392)

This PR improves the log messages to make them easier to consume by users.

* Change unroll to unenroll, that is what we use in the UI too
* Trigger unenroll only when the maxCounter is exceeded (nit)
* Move Artifact has been built with security disable to info. This only happens for internal builds
* Move log message around binary already exists to debug level as this is an expected behaviour
* Be more specific about binary downloads
* For state changes, move the message first. That is the most interesting part for a user

(cherry picked from commit 89d2b36)

Co-authored-by: Nicolas Ruflin <spam@ruflin.com>

x-pack/elastic-agent/pkg/agent/application/gateway/fleet/fleet_gateway.go

@@ -25,6 +25,7 @@ import (
 	"github.com/elastic/beats/v7/x-pack/elastic-agent/pkg/scheduler"
 )
 
+// Max number of times an invalid API Key is checked
 const maxUnauthCounter int = 6
 
 // Default Configuration for the Fleet Gateway.
@@ -244,8 +245,8 @@ func (f *fleetGateway) execute(ctx context.Context) (*fleetapi.CheckinResponse,
 	if isUnauth(err) {
 		f.unauthCounter++
 
-		if f.shouldUnroll() {
-			f.log.Warnf("retrieved unauthorized for '%d' times. Unrolling.", f.unauthCounter)
+		if f.shouldUnenroll() {
+			f.log.Warnf("retrieved an invalid api key error '%d' times. Starting to unenroll the elastic agent.", f.unauthCounter)
 			return &fleetapi.CheckinResponse{
 				Actions: []fleetapi.Action{&fleetapi.ActionUnenroll{ActionID: "", ActionType: "UNENROLL", IsDetected: true}},
 			}, nil
@@ -273,8 +274,9 @@ func (f *fleetGateway) execute(ctx context.Context) (*fleetapi.CheckinResponse,
 	return resp, nil
 }
 
-func (f *fleetGateway) shouldUnroll() bool {
-	return f.unauthCounter >= maxUnauthCounter
+// shouldUnenroll checks if the max number of trying an invalid key is reached
+func (f *fleetGateway) shouldUnenroll() bool {
+	return f.unauthCounter > maxUnauthCounter
 }
 
 func isUnauth(err error) bool {

x-pack/elastic-agent/pkg/agent/cmd/run.go

@@ -130,7 +130,7 @@ func run(streams *cli.IOStreams, override cfgOverrider) error { // Windows: Mark
 	}
 
 	if allowEmptyPgp, _ := release.PGP(); allowEmptyPgp {
-		logger.Warn("Artifact has been build with security disabled. Elastic Agent will not verify signatures of used artifacts.")
+		logger.Info("Artifact has been built with security disabled. Elastic Agent will not verify signatures of the artifacts.")
 	}
 
 	execPath, err := reexecPath()

x-pack/elastic-agent/pkg/agent/operation/operation_fetch.go

@@ -58,7 +58,7 @@ func (o *operationFetch) Check(_ context.Context, _ Application) (bool, error) {
 		return true, nil
 	}
 
-	o.logger.Infof("%s.%s already exists in %s. Skipping operation %s", o.program.BinaryName(), o.program.Version(), fullPath, o.Name())
+	o.logger.Debugf("binary '%s.%s' already exists in %s. Skipping operation %s", o.program.BinaryName(), o.program.Version(), fullPath, o.Name())
 	return false, err
 }
 
@@ -72,7 +72,7 @@ func (o *operationFetch) Run(ctx context.Context, application Application) (err
 
 	fullPath, err := o.downloader.Download(ctx, o.program.Spec(), o.program.Version())
 	if err == nil {
-		o.logger.Infof("operation '%s' downloaded %s.%s into %s", o.Name(), o.program.BinaryName(), o.program.Version(), fullPath)
+		o.logger.Infof("downloaded binary '%s.%s' into '%s' as part of operation '%s'", o.program.BinaryName(), o.program.Version(), fullPath, o.Name())
 	}
 
 	return err

x-pack/elastic-agent/pkg/reporter/log/format.go

@@ -20,8 +20,8 @@ const (
 )
 
 const (
-	// e.g "2006-01-02T15:04:05: type: 'STATE': event type: 'STARTING' message: Application 'filebeat' is starting."
-	defaultLogFormat = "%s: type: '%s': sub_type: '%s' message: %s"
+	// e.g "2006-01-02T15:04:05 - message: Application 'filebeat' is starting. - type: 'STATE' - event type: 'STARTING'"
+	defaultLogFormat = "%s - message: %s - type: '%s' - sub_type: '%s'"
 	timeFormat       = time.RFC3339
 )
 

x-pack/elastic-agent/pkg/reporter/log/reporter.go

@@ -47,9 +47,9 @@ func (r *Reporter) Close() error { return nil }
 func defaultFormatFunc(e reporter.Event) string {
 	return fmt.Sprintf(defaultLogFormat,
 		e.Time().Format(timeFormat),
+		e.Message(),
 		e.Type(),
 		e.SubType(),
-		e.Message(),
 	)
 }
 

x-pack/elastic-agent/pkg/reporter/log/reporter_test.go

@@ -94,5 +94,5 @@ func (testEvent) Payload() map[string]interface{} { return map[string]interface{
 
 func DefaultString(event testEvent) string {
 	timestamp := event.timestamp.Format(timeFormat)
-	return fmt.Sprintf("%s: type: '%s': sub_type: '%s' message: message", timestamp, event.Type(), event.SubType())
+	return fmt.Sprintf("%s - message: message - type: '%s' - sub_type: '%s'", timestamp, event.Type(), event.SubType())
 }