More modernizing logging

Ported block_device/nbd
Made the native CGO return distinct errors in set_edid
Made the cgo_linux (go code) report C-level error return codes
Use defer for server and listener cleanup. Try doing a timeboxed GracefulStop of the server

Author: IDisposable

block_device.go

@@ -9,7 +9,6 @@ import (
 
 	"github.com/jetkvm/kvm/internal/logging"
 	"github.com/pojntfx/go-nbd/pkg/server"
-	"github.com/rs/zerolog"
 )
 
 type remoteImageBackend struct {
@@ -63,14 +62,19 @@ type NBDDevice struct {
 	serverConn net.Conn
 	clientConn net.Conn
 	dev        *os.File
-
-	l *zerolog.Logger
 }
 
 func NewNBDDevice() *NBDDevice {
 	return &NBDDevice{}
 }
 
+func (d *NBDDevice) getLogger() *logging.Context {
+	return logging.NewContext(logging.GetSubsystemLogger("nbd")).
+		With().
+		Str("socket_path", nbdSocketPath).
+		Str("device_path", nbdDevicePath)
+}
+
 func (d *NBDDevice) Start() error {
 	var err error
 
@@ -83,19 +87,10 @@ func (d *NBDDevice) Start() error {
 		return err
 	}
 
-	if d.l == nil {
-		scopedLogger := logging.GetSubsystemLogger("nbd").
-			With().
-			Str("socket_path", nbdSocketPath).
-			Str("device_path", nbdDevicePath).
-			Logger()
-		d.l = &scopedLogger
-	}
-
 	// Remove the socket file if it already exists
 	if _, err := os.Stat(nbdSocketPath); err == nil {
 		if err := os.Remove(nbdSocketPath); err != nil {
-			d.l.Error().Err(err).Msg("failed to remove existing socket file")
+			d.getLogger().Error().Err(err).Msg("failed to remove existing socket file")
 			os.Exit(1)
 		}
 	}
@@ -137,5 +132,5 @@ func (d *NBDDevice) runServerConn() {
 			SupportsMultiConn:  false,
 		})
 
-	d.l.Info().Err(err).Msg("nbd server exited")
+	d.getLogger().Info().Err(err).Msg("nbd server exited")
 }

block_device_linux.go

@@ -11,14 +11,14 @@ func (d *NBDDevice) runClientConn() {
 		ExportName: "jetkvm",
 		BlockSize:  uint32(4 * 1024),
 	})
-	d.l.Info().Err(err).Msg("nbd client exited")
+	d.getLogger().Info().Err(err).Msg("nbd client exited")
 }
 
 func (d *NBDDevice) Close() {
 	if d.dev != nil {
 		err := client.Disconnect(d.dev)
 		if err != nil {
-			d.l.Warn().Err(err).Msg("error disconnecting nbd client")
+			d.getLogger().Warn().Err(err).Msg("error disconnecting nbd client")
 		}
 		_ = d.dev.Close()
 	}

display.go

@@ -193,7 +193,6 @@ func requestDisplayUpdate(shouldWakeDisplay bool, reason string) {
 		if shouldWakeDisplay {
 			wakeDisplay(false, reason)
 		}
-		logging.GetSubsystemLogger("display").Debug().Msg("display updating")
 		// TODO: only run once regardless how many pending updates
 		updateDisplay()
 	}()

internal/native/cgo/edid.c

@@ -81,32 +81,28 @@ int set_edid(uint8_t *edid, size_t size)
     if (size != 128 && size != 256)
     {
         errno = EINVAL;
-        return -1;
+        return -2;
     }
 
-    int fd;
-    struct v4l2_edid v4l2_edid;
-
-    fd = open(V4L_SUBDEV, O_RDWR);
+    int fd = open(V4L_SUBDEV, O_RDWR);
     if (fd < 0)
     {
         log_error("Failed to open device");
-        return -1;
+        return -3;
     }
 
     fix_edid_checksum(edid, size);
 
+    struct v4l2_edid v4l2_edid;
     memset(&v4l2_edid, 0, sizeof(v4l2_edid));
-    v4l2_edid.pad = 0;
-    v4l2_edid.start_block = 0;
     v4l2_edid.blocks = size / 128;
     v4l2_edid.edid = edid;
 
     if (ioctl(fd, VIDIOC_S_EDID, &v4l2_edid) < 0)
     {
         log_error("Failed to set EDID");
         close(fd);
-        return -1;
+        return -4;
     }
 
     close(fd);

internal/native/cgo_linux.go

@@ -75,7 +75,6 @@ func jetkvm_go_log_handler(level C.int, filename *C.cchar_t, funcname *C.cchar_t
 		FuncName: C.GoString(funcname),
 		Line:     int(line),
 	}
-
 	logChan <- logMessage
 }
 
@@ -143,7 +142,7 @@ func videoInit(factor float64) error {
 
 	ret := C.jetkvm_video_init(factorC)
 	if ret != 0 {
-		return fmt.Errorf("failed to initialize video: %d", ret)
+		return fmt.Errorf("failed to initialize video with factor %f: %d", factor, ret)
 	}
 	return nil
 }
@@ -194,7 +193,6 @@ func uiSetVar(name string, value string) {
 
 	nameCStr := C.CString(name)
 	defer C.free(unsafe.Pointer(nameCStr))
-
 	valueCStr := C.CString(value)
 	defer C.free(unsafe.Pointer(valueCStr))
 
@@ -217,6 +215,7 @@ func uiSwitchToScreen(screen string) {
 
 	screenCStr := C.CString(screen)
 	defer C.free(unsafe.Pointer(screenCStr))
+
 	C.jetkvm_ui_load_screen(screenCStr)
 }
 
@@ -236,6 +235,7 @@ func uiObjAddState(objName string, state string) (bool, error) {
 	defer C.free(unsafe.Pointer(objNameCStr))
 	stateCStr := C.CString(state)
 	defer C.free(unsafe.Pointer(stateCStr))
+
 	C.jetkvm_ui_add_state(objNameCStr, stateCStr)
 	return true, nil
 }
@@ -248,6 +248,7 @@ func uiObjClearState(objName string, state string) (bool, error) {
 	defer C.free(unsafe.Pointer(objNameCStr))
 	stateCStr := C.CString(state)
 	defer C.free(unsafe.Pointer(stateCStr))
+
 	C.jetkvm_ui_clear_state(objNameCStr, stateCStr)
 	return true, nil
 }
@@ -268,8 +269,12 @@ func uiObjAddFlag(objName string, flag string) (bool, error) {
 	defer C.free(unsafe.Pointer(objNameCStr))
 	flagCStr := C.CString(flag)
 	defer C.free(unsafe.Pointer(flagCStr))
-	C.jetkvm_ui_add_flag(objNameCStr, flagCStr)
-	return true, nil
+
+	ret := C.jetkvm_ui_add_flag(objNameCStr, flagCStr)
+	if ret < 0 {
+		return false, fmt.Errorf("failed to add flag %s on %s: %d", flag, objName, ret)
+	}
+	return ret == 0, nil
 }
 
 func uiObjClearFlag(objName string, flag string) (bool, error) {
@@ -280,8 +285,12 @@ func uiObjClearFlag(objName string, flag string) (bool, error) {
 	defer C.free(unsafe.Pointer(objNameCStr))
 	flagCStr := C.CString(flag)
 	defer C.free(unsafe.Pointer(flagCStr))
-	C.jetkvm_ui_clear_flag(objNameCStr, flagCStr)
-	return true, nil
+
+	ret := C.jetkvm_ui_clear_flag(objNameCStr, flagCStr)
+	if ret < 0 {
+		return false, fmt.Errorf("failed to clear flag %s on %s: %d", flag, objName, ret)
+	}
+	return ret == 0, nil
 }
 
 func uiObjHide(objName string) (bool, error) {
@@ -311,7 +320,6 @@ func uiObjFadeIn(objName string, duration uint32) (bool, error) {
 	defer C.free(unsafe.Pointer(objNameCStr))
 
 	C.jetkvm_ui_fade_in(objNameCStr, C.u_int32_t(duration))
-
 	return true, nil
 }
 
@@ -323,7 +331,6 @@ func uiObjFadeOut(objName string, duration uint32) (bool, error) {
 	defer C.free(unsafe.Pointer(objNameCStr))
 
 	C.jetkvm_ui_fade_out(objNameCStr, C.u_int32_t(duration))
-
 	return true, nil
 }
 
@@ -333,13 +340,12 @@ func uiLabelSetText(objName string, text string) (bool, error) {
 
 	objNameCStr := C.CString(objName)
 	defer C.free(unsafe.Pointer(objNameCStr))
-
 	textCStr := C.CString(text)
 	defer C.free(unsafe.Pointer(textCStr))
 
 	ret := C.jetkvm_ui_set_text(objNameCStr, textCStr)
 	if ret < 0 {
-		return false, fmt.Errorf("failed to set text: %d", ret)
+		return false, fmt.Errorf("failed to set %s text to %s: %d", objName, text, ret)
 	}
 	return ret == 0, nil
 }
@@ -350,21 +356,17 @@ func uiImgSetSrc(objName string, src string) (bool, error) {
 
 	objNameCStr := C.CString(objName)
 	defer C.free(unsafe.Pointer(objNameCStr))
-
 	srcCStr := C.CString(src)
 	defer C.free(unsafe.Pointer(srcCStr))
 
 	C.jetkvm_ui_set_image(objNameCStr, srcCStr)
-
 	return true, nil
 }
 
 func uiDispSetRotation(rotation uint16) (bool, error) {
 	cgoLock.Lock()
 	defer cgoLock.Unlock()
 
-	nativeLogger.Info().Uint16("rotation", rotation).Msg("setting rotation")
-
 	cRotation := C.u_int16_t(rotation)
 
 	C.jetkvm_ui_set_rotation(cRotation)
@@ -383,7 +385,10 @@ func videoSetStreamQualityFactor(factor float64) error {
 	cgoLock.Lock()
 	defer cgoLock.Unlock()
 
-	C.jetkvm_video_set_quality_factor(C.float(factor))
+	ret := C.jetkvm_video_set_quality_factor(C.float(factor))
+	if ret < 0 {
+		return fmt.Errorf("failed to set video quality factor to %f: %d", factor, ret)
+	}
 	return nil
 }
 
@@ -401,7 +406,11 @@ func videoSetEDID(edid string) error {
 
 	edidCStr := C.CString(edid)
 	defer C.free(unsafe.Pointer(edidCStr))
-	C.jetkvm_video_set_edid(edidCStr)
+
+	ret := C.jetkvm_video_set_edid(edidCStr)
+	if ret < 0 {
+		return fmt.Errorf("failed to set EDID to %s: %d", edid, ret)
+	}
 	return nil
 }
 

internal/native/chan.go

@@ -36,7 +36,8 @@ func (n *Native) handleVideoStateChan() {
 func (n *Native) handleLogChan() {
 	for {
 		entry := <-logChan
-		l := n.nativeContext.
+		l := GetNativeLogger().
+			With().
 			Str("file", entry.File).
 			Str("func", entry.FuncName).
 			Int("line", entry.Line)

internal/native/display.go

@@ -99,18 +99,21 @@ func (n *Native) DisplaySetRotation(rotation uint16) (bool, error) {
 
 // UpdateLabelIfChanged updates the label if the text has changed
 func (n *Native) UpdateLabelIfChanged(objName string, newText string) {
-	l := n.displayContext.Trace().Str("obj", objName).Str("text", newText)
+	logger := GetDisplayLogger().
+		With().
+		Str("obj", objName).
+		Str("text", newText)
 
 	changed, err := n.UIObjSetLabelText(objName, newText)
 	if err != nil {
-		n.displayContext.Warn().Str("obj", objName).Str("text", newText).Err(err).Msg("failed to update label")
+		logger.Warn().Err(err).Msg("failed to update label")
 		return
 	}
 
 	if changed {
-		l.Msg("label changed")
+		logger.Trace().Msg("label changed")
 	} else {
-		l.Msg("label not changed")
+		logger.Trace().Msg("label not changed")
 	}
 }
 
@@ -134,11 +137,18 @@ func (n *Native) SwitchToScreenIf(screenName string, shouldSwitch []string) {
 	if currentScreen == screenName {
 		return
 	}
+
+	logger := GetDisplayLogger().
+		With().
+		Str("from", currentScreen).
+		Str("to", screenName).
+		Strs("from_screens", shouldSwitch)
+
 	if len(shouldSwitch) > 0 && !slices.Contains(shouldSwitch, currentScreen) {
-		n.displayContext.Trace().Str("from", currentScreen).Str("to", screenName).Msg("skipping screen switch")
+		logger.Trace().Msg("skipping screen switch")
 		return
 	}
-	n.displayContext.Info().Str("from", currentScreen).Str("to", screenName).Msg("switching screen")
+	logger.Info().Msg("switching screen")
 	uiSwitchToScreen(screenName)
 }