refactor: structured logging (#351)

Author: ym

block_device.go

@@ -16,8 +16,8 @@ type remoteImageBackend struct {
 
 func (r remoteImageBackend) ReadAt(p []byte, off int64) (n int, err error) {
 	virtualMediaStateMutex.RLock()
-	logger.Debugf("currentVirtualMediaState is %v", currentVirtualMediaState)
-	logger.Debugf("read size: %d, off: %d", len(p), off)
+	logger.Debug().Interface("currentVirtualMediaState", currentVirtualMediaState).Msg("currentVirtualMediaState")
+	logger.Debug().Int64("read size", int64(len(p))).Int64("off", off).Msg("read size and off")
 	if currentVirtualMediaState == nil {
 		return 0, errors.New("image not mounted")
 	}
@@ -93,7 +93,7 @@ func (d *NBDDevice) Start() error {
 	// Remove the socket file if it already exists
 	if _, err := os.Stat(nbdSocketPath); err == nil {
 		if err := os.Remove(nbdSocketPath); err != nil {
-			logger.Errorf("Failed to remove existing socket file %s: %v", nbdSocketPath, err)
+			nativeLogger.Warn().Err(err).Str("socket_path", nbdSocketPath).Msg("Failed to remove existing socket file")
 			os.Exit(1)
 		}
 	}
@@ -134,22 +134,22 @@ func (d *NBDDevice) runServerConn() {
 			MaximumBlockSize:   uint32(16 * 1024),
 			SupportsMultiConn:  false,
 		})
-	logger.Infof("nbd server exited: %v", err)
+	nativeLogger.Info().Err(err).Msg("nbd server exited")
 }
 
 func (d *NBDDevice) runClientConn() {
 	err := client.Connect(d.clientConn, d.dev, &client.Options{
 		ExportName: "jetkvm",
 		BlockSize:  uint32(4 * 1024),
 	})
-	logger.Infof("nbd client exited: %v", err)
+	nativeLogger.Info().Err(err).Msg("nbd client exited")
 }
 
 func (d *NBDDevice) Close() {
 	if d.dev != nil {
 		err := client.Disconnect(d.dev)
 		if err != nil {
-			logger.Warnf("error disconnecting nbd client: %v", err)
+			nativeLogger.Warn().Err(err).Msg("error disconnecting nbd client")
 		}
 		_ = d.dev.Close()
 	}

cloud.go

@@ -253,14 +253,14 @@ func disconnectCloud(reason error) {
 	defer cloudDisconnectLock.Unlock()
 
 	if cloudDisconnectChan == nil {
-		cloudLogger.Tracef("cloud disconnect channel is not set, no need to disconnect")
+		cloudLogger.Trace().Msg("cloud disconnect channel is not set, no need to disconnect")
 		return
 	}
 
 	// just in case the channel is closed, we don't want to panic
 	defer func() {
 		if r := recover(); r != nil {
-			cloudLogger.Infof("cloud disconnect channel is closed, no need to disconnect: %v", r)
+			cloudLogger.Warn().Interface("reason", r).Msg("cloud disconnect channel is closed, no need to disconnect")
 		}
 	}()
 	cloudDisconnectChan <- reason
@@ -289,11 +289,16 @@ func runWebsocketClient() error {
 	header.Set("Authorization", "Bearer "+config.CloudToken)
 	dialCtx, cancelDial := context.WithTimeout(context.Background(), CloudWebSocketConnectTimeout)
 
+	scopedLogger := websocketLogger.With().
+		Str("source", wsURL.Host).
+		Str("sourceType", "cloud").
+		Logger()
+
 	defer cancelDial()
 	c, _, err := websocket.Dial(dialCtx, wsURL.String(), &websocket.DialOptions{
 		HTTPHeader: header,
 		OnPingReceived: func(ctx context.Context, payload []byte) bool {
-			websocketLogger.Infof("ping frame received: %v, source: %s, sourceType: cloud", payload, wsURL.Host)
+			scopedLogger.Info().Bytes("payload", payload).Int("length", len(payload)).Msg("ping frame received")
 
 			metricConnectionTotalPingReceivedCount.WithLabelValues("cloud", wsURL.Host).Inc()
 			metricConnectionLastPingReceivedTimestamp.WithLabelValues("cloud", wsURL.Host).SetToCurrentTime()
@@ -304,19 +309,19 @@ func runWebsocketClient() error {
 	// if the context is canceled, we don't want to return an error
 	if err != nil {
 		if errors.Is(err, context.Canceled) {
-			cloudLogger.Infof("websocket connection canceled")
+			cloudLogger.Info().Msg("websocket connection canceled")
 			return nil
 		}
 		return err
 	}
 	defer c.CloseNow() //nolint:errcheck
-	cloudLogger.Infof("websocket connected to %s", wsURL)
+	cloudLogger.Info().Str("url", wsURL.String()).Msg("websocket connected")
 
 	// set the metrics when we successfully connect to the cloud.
 	wsResetMetrics(true, "cloud", wsURL.Host)
 
 	// we don't have a source for the cloud connection
-	return handleWebRTCSignalWsMessages(c, true, wsURL.Host)
+	return handleWebRTCSignalWsMessages(c, true, wsURL.Host, &scopedLogger)
 }
 
 func authenticateSession(ctx context.Context, c *websocket.Conn, req WebRTCSessionRequest) error {
@@ -327,7 +332,7 @@ func authenticateSession(ctx context.Context, c *websocket.Conn, req WebRTCSessi
 		_ = wsjson.Write(context.Background(), c, gin.H{
 			"error": fmt.Sprintf("failed to initialize OIDC provider: %v", err),
 		})
-		cloudLogger.Errorf("failed to initialize OIDC provider: %v", err)
+		cloudLogger.Warn().Err(err).Msg("failed to initialize OIDC provider")
 		return err
 	}
 
@@ -396,8 +401,8 @@ func handleSessionRequest(ctx context.Context, c *websocket.Conn, req WebRTCSess
 		}()
 	}
 
-	cloudLogger.Info("new session accepted")
-	cloudLogger.Tracef("new session accepted: %v", session)
+	cloudLogger.Info().Interface("session", session).Msg("new session accepted")
+	cloudLogger.Trace().Interface("session", session).Msg("new session accepted")
 	currentSession = session
 	_ = wsjson.Write(context.Background(), c, gin.H{"type": "answer", "data": sd})
 	return nil
@@ -413,21 +418,21 @@ func RunWebsocketClient() {
 
 		// If the network is not up, well, we can't connect to the cloud.
 		if !networkState.Up {
-			cloudLogger.Warn("waiting for network to be up, will retry in 3 seconds")
+			cloudLogger.Warn().Msg("waiting for network to be up, will retry in 3 seconds")
 			time.Sleep(3 * time.Second)
 			continue
 		}
 
 		// If the system time is not synchronized, the API request will fail anyway because the TLS handshake will fail.
 		if isTimeSyncNeeded() && !timeSyncSuccess {
-			cloudLogger.Warn("system time is not synced, will retry in 3 seconds")
+			cloudLogger.Warn().Msg("system time is not synced, will retry in 3 seconds")
 			time.Sleep(3 * time.Second)
 			continue
 		}
 
 		err := runWebsocketClient()
 		if err != nil {
-			cloudLogger.Errorf("websocket client error: %v", err)
+			cloudLogger.Warn().Err(err).Msg("websocket client error")
 			metricCloudConnectionStatus.Set(0)
 			metricCloudConnectionFailureCount.Inc()
 			time.Sleep(5 * time.Second)
@@ -479,7 +484,7 @@ func rpcDeregisterDevice() error {
 			return fmt.Errorf("failed to save configuration after deregistering: %w", err)
 		}
 
-		cloudLogger.Infof("device deregistered, disconnecting from cloud")
+		cloudLogger.Info().Msg("device deregistered, disconnecting from cloud")
 		disconnectCloud(fmt.Errorf("device deregistered"))
 
 		return nil

config.go

@@ -132,7 +132,7 @@ func LoadConfig() {
 	defer configLock.Unlock()
 
 	if config != nil {
-		logger.Info("config already loaded, skipping")
+		logger.Info().Msg("config already loaded, skipping")
 		return
 	}
 
@@ -141,15 +141,15 @@ func LoadConfig() {
 
 	file, err := os.Open(configPath)
 	if err != nil {
-		logger.Debug("default config file doesn't exist, using default")
+		logger.Debug().Msg("default config file doesn't exist, using default")
 		return
 	}
 	defer file.Close()
 
 	// load and merge the default config with the user config
 	loadedConfig := *defaultConfig
 	if err := json.NewDecoder(file).Decode(&loadedConfig); err != nil {
-		logger.Errorf("config file JSON parsing failed, %v", err)
+		logger.Warn().Err(err).Msg("config file JSON parsing failed")
 		return
 	}
 

display.go

@@ -24,7 +24,7 @@ const (
 func switchToScreen(screen string) {
 	_, err := CallCtrlAction("lv_scr_load", map[string]interface{}{"obj": screen})
 	if err != nil {
-		logger.Warnf("failed to switch to screen %s: %v", screen, err)
+		displayLogger.Warn().Err(err).Str("screen", screen).Msg("failed to switch to screen")
 		return
 	}
 	currentScreen = screen
@@ -40,7 +40,7 @@ func updateLabelIfChanged(objName string, newText string) {
 }
 
 func switchToScreenIfDifferent(screenName string) {
-	logger.Infof("switching screen from %s to %s", currentScreen, screenName)
+	displayLogger.Info().Str("from", currentScreen).Str("to", screenName).Msg("switching screen")
 	if currentScreen != screenName {
 		switchToScreen(screenName)
 	}
@@ -74,12 +74,12 @@ var displayInited = false
 
 func requestDisplayUpdate() {
 	if !displayInited {
-		logger.Info("display not inited, skipping updates")
+		displayLogger.Info().Msg("display not inited, skipping updates")
 		return
 	}
 	go func() {
 		wakeDisplay(false)
-		logger.Info("display updating")
+		displayLogger.Info().Msg("display updating")
 		//TODO: only run once regardless how many pending updates
 		updateDisplay()
 	}()
@@ -118,7 +118,7 @@ func setDisplayBrightness(brightness int) error {
 		return err
 	}
 
-	logger.Infof("display: set brightness to %v", brightness)
+	displayLogger.Info().Int("brightness", brightness).Msg("set brightness")
 	return nil
 }
 
@@ -127,7 +127,7 @@ func setDisplayBrightness(brightness int) error {
 func tick_displayDim() {
 	err := setDisplayBrightness(config.DisplayMaxBrightness / 2)
 	if err != nil {
-		logger.Warnf("display: failed to dim display: %s", err)
+		displayLogger.Warn().Err(err).Msg("failed to dim display")
 	}
 
 	dimTicker.Stop()
@@ -140,7 +140,7 @@ func tick_displayDim() {
 func tick_displayOff() {
 	err := setDisplayBrightness(0)
 	if err != nil {
-		logger.Warnf("display: failed to turn off display: %s", err)
+		displayLogger.Warn().Err(err).Msg("failed to turn off display")
 	}
 
 	offTicker.Stop()
@@ -163,7 +163,7 @@ func wakeDisplay(force bool) {
 
 	err := setDisplayBrightness(config.DisplayMaxBrightness)
 	if err != nil {
-		logger.Warnf("display wake failed, %s", err)
+		displayLogger.Warn().Err(err).Msg("failed to wake display")
 	}
 
 	if config.DisplayDimAfterSec != 0 {
@@ -183,7 +183,7 @@ func wakeDisplay(force bool) {
 func watchTsEvents() {
 	ts, err := os.OpenFile(touchscreenDevice, os.O_RDONLY, 0666)
 	if err != nil {
-		logger.Warnf("display: failed to open touchscreen device: %s", err)
+		displayLogger.Warn().Err(err).Msg("failed to open touchscreen device")
 		return
 	}
 
@@ -196,7 +196,7 @@ func watchTsEvents() {
 	for {
 		_, err := ts.Read(buf)
 		if err != nil {
-			logger.Warnf("display: failed to read from touchscreen device: %s", err)
+			displayLogger.Warn().Err(err).Msg("failed to read from touchscreen device")
 			return
 		}
 
@@ -216,7 +216,7 @@ func startBacklightTickers() {
 	}
 
 	if dimTicker == nil && config.DisplayDimAfterSec != 0 {
-		logger.Info("display: dim_ticker has started")
+		displayLogger.Info().Msg("dim_ticker has started")
 		dimTicker = time.NewTicker(time.Duration(config.DisplayDimAfterSec) * time.Second)
 		defer dimTicker.Stop()
 
@@ -231,7 +231,7 @@ func startBacklightTickers() {
 	}
 
 	if offTicker == nil && config.DisplayOffAfterSec != 0 {
-		logger.Info("display: off_ticker has started")
+		displayLogger.Info().Msg("off_ticker has started")
 		offTicker = time.NewTicker(time.Duration(config.DisplayOffAfterSec) * time.Second)
 		defer offTicker.Stop()
 
@@ -251,11 +251,11 @@ func init() {
 
 	go func() {
 		waitCtrlClientConnected()
-		logger.Info("setting initial display contents")
+		displayLogger.Info().Msg("setting initial display contents")
 		time.Sleep(500 * time.Millisecond)
 		updateStaticContents()
 		displayInited = true
-		logger.Info("display inited")
+		displayLogger.Info().Msg("display inited")
 		startBacklightTickers()
 		wakeDisplay(true)
 		requestDisplayUpdate()

fuse.go

@@ -103,7 +103,7 @@ func RunFuseServer() {
 	var err error
 	fuseServer, err = fs.Mount(fuseMountPoint, &FuseRoot{}, opts)
 	if err != nil {
-		logger.Warnf("failed to mount fuse: %v", err)
+		logger.Warn().Err(err).Msg("failed to mount fuse")
 	}
 	fuseServer.Wait()
 }

go.mod

@@ -1,16 +1,15 @@
 module github.com/jetkvm/kvm
 
-go 1.21.0
-
-toolchain go1.21.1
+go 1.23.0
 
 require (
 	github.com/Masterminds/semver/v3 v3.3.0
 	github.com/beevik/ntp v1.3.1
 	github.com/coder/websocket v1.8.13
 	github.com/coreos/go-oidc/v3 v3.11.0
 	github.com/creack/pty v1.1.23
-	github.com/gin-gonic/gin v1.9.1
+	github.com/gin-contrib/logger v1.2.5
+	github.com/gin-gonic/gin v1.10.0
 	github.com/google/uuid v1.6.0
 	github.com/gwatts/rootcerts v0.0.0-20240401182218-3ab9db955caf
 	github.com/hanwen/go-fuse/v2 v2.5.1
@@ -22,38 +21,39 @@ require (
 	github.com/prometheus/client_golang v1.21.0
 	github.com/prometheus/common v0.62.0
 	github.com/psanford/httpreadat v0.1.0
+	github.com/rs/zerolog v1.34.0
 	github.com/vishvananda/netlink v1.3.0
 	go.bug.st/serial v1.6.2
-	golang.org/x/crypto v0.31.0
-	golang.org/x/net v0.33.0
+	golang.org/x/crypto v0.36.0
+	golang.org/x/net v0.38.0
 )
 
 replace github.com/pojntfx/go-nbd v0.3.2 => github.com/chemhack/go-nbd v0.0.0-20241006125820-59e45f5b1e7b
 
 require (
 	github.com/beorn7/perks v1.0.1 // indirect
-	github.com/bytedance/sonic v1.11.6 // indirect
-	github.com/bytedance/sonic/loader v0.1.1 // indirect
+	github.com/bytedance/sonic v1.13.2 // indirect
+	github.com/bytedance/sonic/loader v0.2.4 // indirect
 	github.com/cespare/xxhash/v2 v2.3.0 // indirect
-	github.com/cloudwego/base64x v0.1.4 // indirect
-	github.com/cloudwego/iasm v0.2.0 // indirect
+	github.com/cloudwego/base64x v0.1.5 // indirect
 	github.com/creack/goselect v0.1.2 // indirect
-	github.com/gabriel-vasile/mimetype v1.4.3 // indirect
-	github.com/gin-contrib/sse v0.1.0 // indirect
+	github.com/gabriel-vasile/mimetype v1.4.8 // indirect
+	github.com/gin-contrib/sse v1.0.0 // indirect
 	github.com/go-jose/go-jose/v4 v4.0.2 // indirect
 	github.com/go-playground/locales v0.14.1 // indirect
 	github.com/go-playground/universal-translator v0.18.1 // indirect
-	github.com/go-playground/validator/v10 v10.20.0 // indirect
-	github.com/goccy/go-json v0.10.2 // indirect
+	github.com/go-playground/validator/v10 v10.26.0 // indirect
+	github.com/goccy/go-json v0.10.5 // indirect
 	github.com/json-iterator/go v1.1.12 // indirect
 	github.com/klauspost/compress v1.17.11 // indirect
-	github.com/klauspost/cpuid/v2 v2.2.7 // indirect
+	github.com/klauspost/cpuid/v2 v2.2.10 // indirect
 	github.com/leodido/go-urn v1.4.0 // indirect
+	github.com/mattn/go-colorable v0.1.14 // indirect
 	github.com/mattn/go-isatty v0.0.20 // indirect
 	github.com/modern-go/concurrent v0.0.0-20180306012644-bacd9c7ef1dd // indirect
 	github.com/modern-go/reflect2 v1.0.2 // indirect
 	github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822 // indirect
-	github.com/pelletier/go-toml/v2 v2.2.2 // indirect
+	github.com/pelletier/go-toml/v2 v2.2.3 // indirect
 	github.com/pilebones/go-udev v0.9.0 // indirect
 	github.com/pion/datachannel v1.5.9 // indirect
 	github.com/pion/dtls/v3 v3.0.3 // indirect
@@ -74,10 +74,10 @@ require (
 	github.com/ugorji/go/codec v1.2.12 // indirect
 	github.com/vishvananda/netns v0.0.4 // indirect
 	github.com/wlynxg/anet v0.0.5 // indirect
-	golang.org/x/arch v0.8.0 // indirect
+	golang.org/x/arch v0.15.0 // indirect
 	golang.org/x/oauth2 v0.24.0 // indirect
-	golang.org/x/sys v0.28.0 // indirect
-	golang.org/x/text v0.21.0 // indirect
-	google.golang.org/protobuf v1.36.1 // indirect
+	golang.org/x/sys v0.32.0 // indirect
+	golang.org/x/text v0.23.0 // indirect
+	google.golang.org/protobuf v1.36.6 // indirect
 	gopkg.in/yaml.v3 v3.0.1 // indirect
 )