Repository: lima-vm/lima
Pull request #2233 (2024-03-06 08:31:40)

Propagate all logging fields to the tty logger
The fields are serialized in JSON by the hostagent and then printed by the `limactl start` command to the console, so need to be explicitly added back to the logger entry.

This PR is in response to https://github.com/lima-vm/lima/pull/2228#discussion_r1513910877.

Note that nested structures (like `events.Event`) will be flattened by the standard logger, e.g.

```golang
       err := errors.New("oops")
       ev := events.Event{
               Status: events.Status{
                       Running: true,
                       Errors:  []string{"Error one", "Error two"},
               },
       }
       logrus.WithError(err).WithField("events", ev).Warn("Log message with error")
```

will result in

```console
WARN[0020] [hostagent] Log message with error            error=oops events="map[status:map[errors:[Error one Error two] running:true] time:0001-01-01T00:00:00Z]"
```
<img width="999" alt="CleanShot 2024-03-06 at 00 26 57@2x" src="https://github.com/lima-vm/lima/assets/78947/c5711b2f-4a87-41a0-a388-fc108bc6d989">

The change to `qemu_driver.go` is needed to avoid the ugly `<nil>` error in

```
INFO[0004] [hostagent] QEMU has exited                   error="<nil>"
```

@balajiv113 Your inotify PR has additional logging entries with duplicate `err` which should be changed if this PR is accepted/merged:

```
pkg/hostagent/hostagent.go
604:				logrus.WithError(err).Warn("failed to start inotify", err)

pkg/hostagent/inotify.go
52:				logrus.WithError(err).Warn("failed to send inotify", err)
```

jandubois: I made one more change to replace the `switch lv` block with this logic, which feels clearer to me:

```golang
if !logger.IsLevelEnabled(lv) {
	return
}
// …
if lv <= logrus.FatalLevel {
	entry = entry.WithField("level", lv)
	lv = logrus.ErrorLevel
}
entry.Log(lv, header+j.Msg)
```

jandubois: @AkihiroSuda Speaking of comments, I think this line could use some explanation:

```
if !j.Time.IsZero() && !begin.IsZero() && begin.After(j.Time.Add(epsilon)) {
	return
}
```

It seems to be added by 21b7cb0e to control logging for `limactl stop` iiuc, and seems to ignore log messages that are more than one second before the `begin` value.

It is not clear to me why this is needed; I assume if there is still a backlog of unprocessed log messages from before the `stop` command, that you don't want to dump them out to the terminal?
jandubois: I just realized that there are tests in `logrusutil_test.go` that should be updated too. I won't have time for this for the next few days though, so will turn this into draft for now.

I don't plan on changing anything else but the tests though, so feel free to review the draft code in case you have any feedback!
jandubois: > I won't have time for this for the next few days though, so will turn this into draft for now.

I added the tests and took it out of draft; I think it is good now.

Patch:
diff --git a/go.mod b/go.mod
index 22068d9a..9309ce98 100644
--- a/go.mod
+++ b/go.mod
@@ -44,8 +44,8 @@ require (
 	golang.org/x/sync v0.6.0
 	golang.org/x/sys v0.18.0
 	golang.org/x/text v0.14.0
-	google.golang.org/grpc v1.62.1
-	google.golang.org/protobuf v1.33.0
+	google.golang.org/grpc v1.62.0
+	google.golang.org/protobuf v1.32.0
 	gopkg.in/op/go-logging.v1 v1.0.0-20160211212156-b2cb9fa56473
 	gopkg.in/yaml.v3 v3.0.1
 	gotest.tools/v3 v3.5.1
diff --git a/go.sum b/go.sum
index c0287c07..0f3932e6 100644
--- a/go.sum
+++ b/go.sum
@@ -418,12 +418,12 @@ google.golang.org/appengine v1.6.8 h1:IhEN5q69dyKagZPYMSdIjS2HqprW324FRQZJcGqPAs
 google.golang.org/appengine v1.6.8/go.mod h1:1jJ3jBArFh5pcgW8gCtRJnepW8FzD1V44FJffLiz/Ds=
 google.golang.org/genproto/googleapis/rpc v0.0.0-20240123012728-ef4313101c80 h1:AjyfHzEPEFp/NpvfN5g+KDla3EMojjhRVZc1i7cj+oM=
 google.golang.org/genproto/googleapis/rpc v0.0.0-20240123012728-ef4313101c80/go.mod h1:PAREbraiVEVGVdTZsVWjSbbTtSyGbAgIIvni8a8CD5s=
-google.golang.org/grpc v1.62.1 h1:B4n+nfKzOICUXMgyrNd19h/I9oH0L1pizfk1d4zSgTk=
-google.golang.org/grpc v1.62.1/go.mod h1:IWTG0VlJLCh1SkC58F7np9ka9mx/WNkjl4PGJaiq+QE=
+google.golang.org/grpc v1.62.0 h1:HQKZ/fa1bXkX1oFOvSjmZEUL8wLSaZTjCcLAlmZRtdk=
+google.golang.org/grpc v1.62.0/go.mod h1:IWTG0VlJLCh1SkC58F7np9ka9mx/WNkjl4PGJaiq+QE=
 google.golang.org/protobuf v1.26.0-rc.1/go.mod h1:jlhhOSvTdKEhbULTjvd4ARK9grFBp09yW+WbY/TyQbw=
 google.golang.org/protobuf v1.26.0/go.mod h1:9q0QmTI4eRPtz6boOQmLYwt+qCgq0jsYwAQnmE0givc=
-google.golang.org/protobuf v1.33.0 h1:uNO2rsAINq/JlFpSdYEKIZ0uKD/R9cpdv0T+yoGwGmI=
-google.golang.org/protobuf v1.33.0/go.mod h1:c6P6GXX6sHbq/GpV6MGZEdwhWPcYBgnhAHhKbcUYpos=
+google.golang.org/protobuf v1.32.0 h1:pPC6BG5ex8PDFnkbrGU3EixyhKcQ2aDuBS36lqK/C7I=
+google.golang.org/protobuf v1.32.0/go.mod h1:c6P6GXX6sHbq/GpV6MGZEdwhWPcYBgnhAHhKbcUYpos=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
 gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c h1:Hei/4ADfdWqJk1ZMxUNpqntNwaWcugrBjAiHlqqRiVk=
 gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c/go.mod h1:JHkPIbrfpd72SG/EVd6muEfDQjcINNoR0C8j2r3qZ4Q=
diff --git a/pkg/hostagent/hostagent.go b/pkg/hostagent/hostagent.go
index 6247ecbe..27e5160e 100644
--- a/pkg/hostagent/hostagent.go
+++ b/pkg/hostagent/hostagent.go
@@ -598,12 +598,12 @@ func (a *HostAgent) watchGuestAgentEvents(ctx context.Context) {
 		if err == nil {
 			if err := a.processGuestAgentEvents(ctx, client); err != nil {
 				if !errors.Is(err, context.Canceled) {
-					logrus.WithError(err).Warn("guest agent events closed unexpectedly", err)
+					logrus.WithError(err).Warn("guest agent events closed unexpectedly")
 				}
 			}
 		} else {
 			if !errors.Is(err, context.Canceled) {
-				logrus.WithError(err).Warn("connection to the guest agent was closed unexpectedly", err)
+				logrus.WithError(err).Warn("connection to the guest agent was closed unexpectedly")
 			}
 		}
 		select {
diff --git a/pkg/logrusutil/logrusutil.go b/pkg/logrusutil/logrusutil.go
index 994996e7..75fa0365 100644
--- a/pkg/logrusutil/logrusutil.go
+++ b/pkg/logrusutil/logrusutil.go
@@ -19,10 +19,14 @@ func PropagateJSON(logger *logrus.Logger, jsonLine []byte, header string, begin
 	}
 
 	var (
-		lv  logrus.Level
-		j   JSON
-		err error
+		entry  *logrus.Entry
+		fields logrus.Fields
+		lv     logrus.Level
+		j      JSON
+		err    error
 	)
+	entry = logrus.NewEntry(logger)
+
 	if err := json.Unmarshal(jsonLine, &j); err != nil {
 		goto fallback
 	}
@@ -33,24 +37,26 @@ func PropagateJSON(logger *logrus.Logger, jsonLine []byte, header string, begin
 	if err != nil {
 		goto fallback
 	}
-	switch lv {
-	case logrus.PanicLevel, logrus.FatalLevel:
-		logger.WithField("level", lv).Error(header + j.Msg)
-	case logrus.ErrorLevel:
-		logger.Error(header + j.Msg)
-	case logrus.WarnLevel:
-		logger.Warn(header + j.Msg)
-	case logrus.InfoLevel:
-		logger.Info(header + j.Msg)
-	case logrus.DebugLevel:
-		logger.Debug(header + j.Msg)
-	case logrus.TraceLevel:
-		logger.Trace(header + j.Msg)
+	entry = entry.WithTime(j.Time)
+	// Unmarshal jsonLine once more to capture all the "extra" fields that have been added by
+	// WithError() and WithField(). The regular fields "level", "msg", and "time" are already
+	// unmarshalled into j and are handled specially. They must not be added again.
+	if err := json.Unmarshal(jsonLine, &fields); err == nil {
+		delete(fields, "level")
+		delete(fields, "msg")
+		delete(fields, "time")
+		entry = entry.WithFields(fields)
+	}
+	// Don't exit on Fatal or Panic entries
+	if lv <= logrus.FatalLevel {
+		entry = entry.WithField("level", lv)
+		lv = logrus.ErrorLevel
 	}
+	entry.Log(lv, header+j.Msg)
 	return
 
 fallback:
-	logger.Info(header + string(jsonLine))
+	entry.Info(header + string(jsonLine))
 }
 
 // JSON is the type used in logrus.JSONFormatter
diff --git a/pkg/qemu/qemu_driver.go b/pkg/qemu/qemu_driver.go
index d4306a92..7f00d3f9 100644
--- a/pkg/qemu/qemu_driver.go
+++ b/pkg/qemu/qemu_driver.go
@@ -324,7 +324,11 @@ func (l *LimaQemuDriver) shutdownQEMU(ctx context.Context, timeout time.Duration
 	deadline := time.After(timeout)
 	select {
 	case qWaitErr := <-qWaitCh:
-		logrus.WithError(qWaitErr).Info("QEMU has exited")
+		entry := logrus.NewEntry(logrus.StandardLogger())
+		if qWaitErr != nil {
+			entry = entry.WithError(qWaitErr)
+		}
+		entry.Info("QEMU has exited")
 		_ = l.removeVNCFiles()
 		return errors.Join(qWaitErr, l.killVhosts())
 	case <-deadline:


Test patch:
diff --git a/pkg/logrusutil/logrusutil_test.go b/pkg/logrusutil/logrusutil_test.go
index a3a6dd90..84e95c74 100644
--- a/pkg/logrusutil/logrusutil_test.go
+++ b/pkg/logrusutil/logrusutil_test.go
@@ -81,6 +81,35 @@ func TestPropagateJSON(t *testing.T) {
 
 		assert.Equal(t, "level=error msg=header fields.level=fatal\n", actual.String())
 	})
+	t.Run("SetLevel", func(t *testing.T) {
+		actual := &bytes.Buffer{}
+		logger := loggerWithoutTs(actual)
+		logger.SetLevel(logrus.ErrorLevel)
+		jsonLine := []byte(`{"level": "warning"}`)
+
+		PropagateJSON(logger, jsonLine, "header", time.Time{})
+
+		assert.Equal(t, "", actual.String())
+	})
+	t.Run("extra fields", func(t *testing.T) {
+		actual := &bytes.Buffer{}
+		logger := loggerWithoutTs(actual)
+		jsonLine := []byte(`{"level": "warning", "error": "oops", "extra": "field"}`)
+
+		PropagateJSON(logger, jsonLine, "header", time.Time{})
+
+		assert.Equal(t, "level=warning msg=header error=oops extra=field\n", actual.String())
+	})
+	t.Run("timestamp", func(t *testing.T) {
+		actual := &bytes.Buffer{}
+		logger := loggerWithoutTs(actual)
+		logger.SetFormatter(&logrus.TextFormatter{DisableTimestamp: false})
+		jsonLine := []byte(`{"level": "warning", "time": "2024-03-06T00:20:53-08:00"}`)
+
+		PropagateJSON(logger, jsonLine, "header", time.Time{})
+
+		assert.Equal(t, "time=\"2024-03-06T00:20:53-08:00\" level=warning msg=header\n", actual.String())
+	})
 	t.Run("empty json line", func(t *testing.T) {
 		actual := &bytes.Buffer{}
 		logger := loggerWithoutTs(actual)