Repository: lima-vm/lima
Pull request #2074 (2023-12-14 11:27:31)

pkg/logrusutil: Fix PropagateJSON to use logger; add tests
This PR refactors the function `logrusutil.PropagateJSON` by removing `goto`, changing fallback `logrus.Info` (which prints to stderr) to `logger.Info`, and adding unit tests.


Patch:
diff --git a/.github/workflows/release.yml b/.github/workflows/release.yml
index 8db5768c..2240dd52 100644
--- a/.github/workflows/release.yml
+++ b/.github/workflows/release.yml
@@ -34,7 +34,7 @@ jobs:
     - name: Make darwin artifacts
       run: make artifacts-darwin
     - name: "Upload artifacts"
-      uses: actions/upload-artifact@v4
+      uses: actions/upload-artifact@v3
       with:
         name: artifacts-darwin
         path: _artifacts/
@@ -45,7 +45,7 @@ jobs:
     timeout-minutes: 20
     steps:
     - uses: actions/checkout@v4
-    - uses: actions/download-artifact@v4
+    - uses: actions/download-artifact@v3
       with:
         name: artifacts-darwin
         path: _artifacts/
diff --git a/pkg/cidata/cidata.TEMPLATE.d/boot/07-etc-environment.sh b/pkg/cidata/cidata.TEMPLATE.d/boot/07-etc-environment.sh
index 48f6700e..4cd8b07c 100644
--- a/pkg/cidata/cidata.TEMPLATE.d/boot/07-etc-environment.sh
+++ b/pkg/cidata/cidata.TEMPLATE.d/boot/07-etc-environment.sh
@@ -4,7 +4,6 @@ set -eux
 # /etc/environment must be written after 04-persistent-data-volume.sh has run to
 # make sure the changes on a restart are applied to the persisted version.
 
-orig=$(test -f /etc/environment && cat /etc/environment)
 if [ -e /etc/environment ]; then
 	sed -i '/#LIMA-START/,/#LIMA-END/d' /etc/environment
 fi
@@ -14,10 +13,13 @@ cat "${LIMA_CIDATA_MNT}/etc_environment" >>/etc/environment
 # /etc/environment was updated, so we need to kill it to make sure it will
 # restart with the updated environment before "linger" is being enabled.
 
-if command -v loginctl >/dev/null 2>&1 && [ "${orig}" != "$(cat /etc/environment)" ]; then
+if command -v loginctl >/dev/null 2>&1; then
 	loginctl terminate-user "${LIMA_CIDATA_USER}" || true
 fi
 
+# Make sure the guestagent socket from a previous boot is removed before we open the "lima-ssh-ready" gate.
+rm -f /run/lima-guest-agent.sock
+
 # Signal that provisioning is done. The instance-id in the meta-data file changes on every boot,
 # so any copy from a previous boot cycle will have different content.
 cp "${LIMA_CIDATA_MNT}"/meta-data /run/lima-ssh-ready
diff --git a/pkg/logrusutil/logrusutil.go b/pkg/logrusutil/logrusutil.go
index 3703e7c9..994996e7 100644
--- a/pkg/logrusutil/logrusutil.go
+++ b/pkg/logrusutil/logrusutil.go
@@ -50,7 +50,7 @@ func PropagateJSON(logger *logrus.Logger, jsonLine []byte, header string, begin
 	return
 
 fallback:
-	logrus.Info(header + string(jsonLine))
+	logger.Info(header + string(jsonLine))
 }
 
 // JSON is the type used in logrus.JSONFormatter


Test patch:
diff --git a/pkg/logrusutil/logrusutil_test.go b/pkg/logrusutil/logrusutil_test.go
new file mode 100644
index 00000000..a3a6dd90
--- /dev/null
+++ b/pkg/logrusutil/logrusutil_test.go
@@ -0,0 +1,123 @@
+package logrusutil
+
+import (
+	"bytes"
+	"testing"
+	"time"
+
+	"github.com/sirupsen/logrus"
+	"gotest.tools/v3/assert"
+)
+
+func TestPropagateJSON(t *testing.T) {
+	loggerWithoutTs := func(output *bytes.Buffer) *logrus.Logger {
+		logger := logrus.New()
+		logger.SetOutput(output)
+		logger.SetLevel(logrus.TraceLevel)
+		logger.SetFormatter(&logrus.TextFormatter{DisableTimestamp: true})
+		return logger
+	}
+
+	t.Run("trace level", func(t *testing.T) {
+		actual := &bytes.Buffer{}
+		logger := loggerWithoutTs(actual)
+		jsonLine := []byte(`{"level": "trace"}`)
+
+		PropagateJSON(logger, jsonLine, "header", time.Time{})
+
+		assert.Equal(t, "level=trace msg=header\n", actual.String())
+	})
+	t.Run("debug level", func(t *testing.T) {
+		actual := &bytes.Buffer{}
+		logger := loggerWithoutTs(actual)
+		jsonLine := []byte(`{"level": "debug"}`)
+
+		PropagateJSON(logger, jsonLine, "header", time.Time{})
+
+		assert.Equal(t, "level=debug msg=header\n", actual.String())
+	})
+	t.Run("info level", func(t *testing.T) {
+		actual := &bytes.Buffer{}
+		logger := loggerWithoutTs(actual)
+		jsonLine := []byte(`{"level": "info"}`)
+
+		PropagateJSON(logger, jsonLine, "header", time.Time{})
+
+		assert.Equal(t, "level=info msg=header\n", actual.String())
+	})
+	t.Run("error level", func(t *testing.T) {
+		actual := &bytes.Buffer{}
+		logger := loggerWithoutTs(actual)
+		jsonLine := []byte(`{"level": "error"}`)
+
+		PropagateJSON(logger, jsonLine, "header", time.Time{})
+
+		assert.Equal(t, "level=error msg=header\n", actual.String())
+	})
+	t.Run("warning level", func(t *testing.T) {
+		actual := &bytes.Buffer{}
+		logger := loggerWithoutTs(actual)
+		jsonLine := []byte(`{"level": "warning"}`)
+
+		PropagateJSON(logger, jsonLine, "header", time.Time{})
+
+		assert.Equal(t, "level=warning msg=header\n", actual.String())
+	})
+	t.Run("panic level", func(t *testing.T) {
+		actual := &bytes.Buffer{}
+		logger := loggerWithoutTs(actual)
+		jsonLine := []byte(`{"level": "panic"}`)
+
+		PropagateJSON(logger, jsonLine, "header", time.Time{})
+
+		assert.Equal(t, "level=error msg=header fields.level=panic\n", actual.String())
+	})
+	t.Run("fatal level", func(t *testing.T) {
+		actual := &bytes.Buffer{}
+		logger := loggerWithoutTs(actual)
+		jsonLine := []byte(`{"level": "fatal"}`)
+
+		PropagateJSON(logger, jsonLine, "header", time.Time{})
+
+		assert.Equal(t, "level=error msg=header fields.level=fatal\n", actual.String())
+	})
+	t.Run("empty json line", func(t *testing.T) {
+		actual := &bytes.Buffer{}
+		logger := loggerWithoutTs(actual)
+		jsonLine := []byte{}
+
+		PropagateJSON(logger, jsonLine, "header", time.Time{})
+
+		assert.Equal(t, "", actual.String())
+	})
+	t.Run("unmarshal failed", func(t *testing.T) {
+		actual := &bytes.Buffer{}
+		logger := loggerWithoutTs(actual)
+		jsonLine := []byte(`"`)
+
+		PropagateJSON(logger, jsonLine, "header", time.Time{})
+
+		assert.Equal(t, `level=info msg="header\""
+`, actual.String())
+	})
+	t.Run("begin time after time in jsonLine", func(t *testing.T) {
+		actual := &bytes.Buffer{}
+		logger := loggerWithoutTs(actual)
+		jsonLine := []byte(`{"level": "info", "time": "2023-12-01T00:00:00.0000+00:00"}`)
+		begin := time.Date(2023, time.December, 15, 0, 0, 0, 0, time.UTC)
+
+		PropagateJSON(logger, jsonLine, "header", begin)
+
+		assert.Equal(t, "", actual.String())
+	})
+	t.Run("parse level failed", func(t *testing.T) {
+		actual := &bytes.Buffer{}
+		logger := loggerWithoutTs(actual)
+		jsonLine := []byte(`{"level": "info", "level": "unknown level"}`)
+
+		PropagateJSON(logger, jsonLine, "header", time.Time{})
+
+		assert.Equal(t, `level=info msg="header{\"level\": \"info\", \"level\": \"unknown level\"}"
+`, actual.String())
+	})
+}