refactor: use structured logging

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.String()).
+		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()
 }

hw.go

@@ -42,7 +42,7 @@ func GetDeviceID() string {
 	deviceIDOnce.Do(func() {
 		serial, err := extractSerialNumber()
 		if err != nil {
-			logger.Warn("unknown serial number, the program likely not running on RV1106")
+			logger.Warn().Msg("unknown serial number, the program likely not running on RV1106")
 			deviceID = "unknown_device_id"
 		} else {
 			deviceID = serial
@@ -54,7 +54,7 @@ func GetDeviceID() string {
 func runWatchdog() {
 	file, err := os.OpenFile("/dev/watchdog", os.O_WRONLY, 0)
 	if err != nil {
-		logger.Warnf("unable to open /dev/watchdog: %v, skipping watchdog reset", err)
+		logger.Warn().Err(err).Msg("unable to open /dev/watchdog, skipping watchdog reset")
 		return
 	}
 	defer file.Close()
@@ -65,13 +65,13 @@ func runWatchdog() {
 		case <-ticker.C:
 			_, err = file.Write([]byte{0})
 			if err != nil {
-				logger.Errorf("error writing to /dev/watchdog, system may reboot: %v", err)
+				logger.Warn().Err(err).Msg("error writing to /dev/watchdog, system may reboot")
 			}
 		case <-appCtx.Done():
 			//disarm watchdog with magic value
 			_, err := file.Write([]byte("V"))
 			if err != nil {
-				logger.Errorf("failed to disarm watchdog, system may reboot: %v", err)
+				logger.Warn().Err(err).Msg("failed to disarm watchdog, system may reboot")
 			}
 			return
 		}

internal/pion/logging/logger.go

@@ -6,6 +6,7 @@ import (
 	"fmt"
 	"io"
 	"os"
+	"runtime"
 	"strings"
 	"sync"
 	"time"
@@ -16,16 +17,13 @@ import (
 var defaultOutput io.Writer = zerolog.ConsoleWriter{
 	Out:           os.Stdout,
 	TimeFormat:    time.RFC3339,
-	PartsOrder:    []string{"time", "level", "scope", "message"},
-	FieldsExclude: []string{"scope"},
+	PartsOrder:    []string{"time", "level", "scope", "component", "message"},
+	FieldsExclude: []string{"scope", "component"},
 	FormatPartValueByName: func(value interface{}, name string) string {
 		val := fmt.Sprintf("%s", value)
-		if name == "scope" {
-			if strings.HasPrefix(val, "jetkvm/") {
-				return val[7:]
-			} else {
-				// scope without prefix, we assume it's from the pion library
-				return fmt.Sprintf("pion/%s", val)
+		if name == "component" {
+			if value == nil {
+				return "-"
 			}
 		}
 		return val
@@ -182,7 +180,19 @@ func NewDefaultLeveledLoggerForScope(scope string, level LogLevel, writer io.Wri
 	if writer == nil {
 		writer = defaultOutput
 	}
-	zerologWriter := zerolog.New(writer).With().Timestamp().Str("scope", scope).Logger()
+
+	z := zerolog.New(writer).Level(toZerologLevel(level)).With().Timestamp()
+
+	// scope will be changed to the component name if it's from the pion library
+	_, file, _, _ := runtime.Caller(2)
+	if strings.Contains(file, "github.com/pion/") {
+		z = z.Str("scope", "pion").Str("component", scope)
+	} else {
+		z = z.Str("scope", scope)
+	}
+
+	zerologWriter := z.Logger()
+
 	logger := &DefaultLeveledLogger{
 		writer: &zerologWriter,
 		level:  level,