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.

Signed-off-by: Jan Dubois <[email protected]>

Author: jandubois

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 {

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

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)

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: