Fix USB Gadget polling/writing to recover from errors

block_device.go

@@ -7,6 +7,7 @@ import (
 	"os"
 	"time"
 
+	"github.com/jetkvm/kvm/internal/logging"
 	"github.com/pojntfx/go-nbd/pkg/server"
 	"github.com/rs/zerolog"
 )
@@ -16,6 +17,8 @@ type remoteImageBackend struct {
 
 func (r remoteImageBackend) ReadAt(p []byte, off int64) (n int, err error) {
 	virtualMediaStateMutex.RLock()
+
+	logger := logging.GetSubsystemLogger("nbd")
 	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 {
@@ -60,14 +63,21 @@ type NBDDevice struct {
 	serverConn net.Conn
 	clientConn net.Conn
 	dev        *os.File
-
-	l *zerolog.Logger
 }
 
 func NewNBDDevice() *NBDDevice {
 	return &NBDDevice{}
 }
 
+func (d *NBDDevice) getLogger() *zerolog.Logger {
+	logger := logging.GetSubsystemLogger("nbd").
+		With().
+		Str("socket_path", nbdSocketPath).
+		Str("device_path", nbdDevicePath).
+		Logger()
+	return &logger
+}
+
 func (d *NBDDevice) Start() error {
 	var err error
 
@@ -80,18 +90,10 @@ func (d *NBDDevice) Start() error {
 		return err
 	}
 
-	if d.l == nil {
-		scopedLogger := nbdLogger.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)
 		}
 	}
@@ -133,5 +135,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()
 	}

block_device_notlinux.go

@@ -7,11 +7,11 @@ import (
 )
 
 func (d *NBDDevice) runClientConn() {
-	d.l.Error().Msg("platform not supported")
+	d.getLogger().Error().Msg("platform not supported")
 	os.Exit(1)
 }
 
 func (d *NBDDevice) Close() {
-	d.l.Error().Msg("platform not supported")
+	d.getLogger().Error().Msg("platform not supported")
 	os.Exit(1)
 }

cloud.go

@@ -13,14 +13,15 @@ import (
 
 	"github.com/coder/websocket/wsjson"
 	"github.com/google/uuid"
+	"github.com/jetkvm/kvm/internal/logging"
+	"github.com/jetkvm/kvm/internal/utils"
 	"github.com/prometheus/client_golang/prometheus"
 	"github.com/prometheus/client_golang/prometheus/promauto"
 
 	"github.com/coreos/go-oidc/v3/oidc"
 
 	"github.com/coder/websocket"
 	"github.com/gin-gonic/gin"
-	"github.com/rs/zerolog"
 )
 
 type CloudRegisterRequest struct {
@@ -284,6 +285,7 @@ func disconnectCloud(reason error) {
 	cloudDisconnectLock.Lock()
 	defer cloudDisconnectLock.Unlock()
 
+	cloudLogger := logging.GetSubsystemLogger("cloud")
 	if cloudDisconnectChan == nil {
 		cloudLogger.Trace().Msg("cloud disconnect channel is not set, no need to disconnect")
 		return
@@ -323,18 +325,13 @@ func runWebsocketClient() error {
 	header.Set("Authorization", "Bearer "+config.CloudToken)
 	dialCtx, cancelDial := context.WithTimeout(context.Background(), CloudWebSocketConnectTimeout)
 
-	l := websocketLogger.With().
-		Str("source", wsURL.Host).
-		Str("sourceType", "cloud").
-		Logger()
-
-	scopedLogger := &l
+	logger := logging.GetSubsystemLogger("cloud").With().Str("subcomponent", "websocket").Str("source", wsURL.Host).Str("sourceType", "cloud").Logger()
 
 	defer cancelDial()
 	c, resp, err := websocket.Dial(dialCtx, wsURL.String(), &websocket.DialOptions{
 		HTTPHeader: header,
 		OnPingReceived: func(ctx context.Context, payload []byte) bool {
-			scopedLogger.Debug().Bytes("payload", payload).Int("length", len(payload)).Msg("ping frame received")
+			logger.Debug().Object("data", utils.ByteSlice(payload)).Int("length", len(payload)).Msg("ping frame received")
 
 			metricConnectionTotalPingReceivedCount.WithLabelValues("cloud", wsURL.Host).Inc()
 			metricConnectionLastPingReceivedTimestamp.WithLabelValues("cloud", wsURL.Host).SetToCurrentTime()
@@ -356,15 +353,13 @@ func runWebsocketClient() error {
 
 	if connectionId == "" {
 		connectionId = uuid.New().String()
-		scopedLogger.Warn().
+		logger.Warn().
 			Str("connectionId", connectionId).
 			Msg("no connection id received from the server, generating a new one")
 	}
 
-	lWithConnectionId := scopedLogger.With().
-		Str("connectionID", connectionId).
-		Logger()
-	scopedLogger = &lWithConnectionId
+	logger = logger.With().Str("connectionID", connectionId).Logger()
+	cloudLogger := logging.GetSubsystemLogger("cloud")
 
 	// if the context is canceled, we don't want to return an error
 	if err != nil {
@@ -386,7 +381,7 @@ func runWebsocketClient() error {
 	wsResetMetrics(true, "cloud", wsURL.Host)
 
 	// we don't have a source for the cloud connection
-	return handleWebRTCSignalWsMessages(c, true, wsURL.Host, connectionId, scopedLogger)
+	return handleWebRTCSignalWsMessages(c, true, wsURL.Host, connectionId)
 }
 
 func authenticateSession(ctx context.Context, c *websocket.Conn, req WebRTCSessionRequest) error {
@@ -397,7 +392,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.Warn().Err(err).Msg("failed to initialize OIDC provider")
+		logging.GetSubsystemLogger("cloud").Warn().Err(err).Msg("failed to initialize OIDC provider")
 		return err
 	}
 
@@ -426,7 +421,6 @@ func handleSessionRequest(
 	req WebRTCSessionRequest,
 	isCloudConnection bool,
 	source string,
-	scopedLogger *zerolog.Logger,
 ) error {
 	var sourceType string
 	if isCloudConnection {
@@ -453,7 +447,6 @@ func handleSessionRequest(
 		IsCloud:    isCloudConnection,
 		LocalIP:    req.IP,
 		ICEServers: req.ICEServers,
-		Logger:     scopedLogger,
 	})
 	if err != nil {
 		_ = wsjson.Write(context.Background(), c, gin.H{"error": err})
@@ -474,11 +467,10 @@ func handleSessionRequest(
 		}()
 	}
 
-	cloudLogger.Info().Interface("session", session).Msg("new session accepted")
-	cloudLogger.Trace().Interface("session", session).Msg("new session accepted")
+	logging.GetSubsystemLogger("cloud").Info().Interface("session", session).Msg("new session accepted")
 
 	// Cancel any ongoing keyboard macro when session changes
-	cancelKeyboardMacro()
+	_ = cancelKeyboardMacro()
 
 	currentSession = session
 	_ = wsjson.Write(context.Background(), c, gin.H{"type": "answer", "data": sd})
@@ -495,21 +487,21 @@ func RunWebsocketClient() {
 
 		// If the network is not up, well, we can't connect to the cloud.
 		if !networkManager.IsOnline() {
-			cloudLogger.Warn().Msg("waiting for network to be online, will retry in 3 seconds")
+			logging.GetSubsystemLogger("cloud").Warn().Msg("waiting for network to be online, 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() && !timeSync.IsSyncSuccess() {
-			cloudLogger.Warn().Msg("system time is not synced, will retry in 3 seconds")
+			logging.GetSubsystemLogger("cloud").Warn().Msg("system time is not synced, will retry in 3 seconds")
 			time.Sleep(3 * time.Second)
 			continue
 		}
 
 		err := runWebsocketClient()
 		if err != nil {
-			cloudLogger.Warn().Err(err).Msg("websocket client error")
+			logging.GetSubsystemLogger("cloud").Warn().Err(err).Msg("websocket client error")
 			metricCloudConnectionStatus.Set(0)
 			metricCloudConnectionFailureCount.Inc()
 			time.Sleep(5 * time.Second)
@@ -561,7 +553,7 @@ func rpcDeregisterDevice() error {
 			return fmt.Errorf("failed to save configuration after deregistering: %w", err)
 		}
 
-		cloudLogger.Info().Msg("device deregistered, disconnecting from cloud")
+		logging.GetSubsystemLogger("cloud").Info().Msg("device deregistered, disconnecting from cloud")
 		disconnectCloud(fmt.Errorf("device deregistered"))
 
 		setCloudConnectionState(CloudConnectionStateNotConfigured)

cmd/main.go

@@ -11,10 +11,11 @@ import (
 	"syscall"
 	"time"
 
-	"github.com/erikdubbelboer/gspt"
 	"github.com/jetkvm/kvm"
 	"github.com/jetkvm/kvm/internal/native"
 	"github.com/jetkvm/kvm/internal/supervisor"
+
+	"github.com/erikdubbelboer/gspt"
 )
 
 var (

config.go

@@ -11,7 +11,7 @@
 	"github.com/jetkvm/kvm/internal/confparser"
 	"github.com/jetkvm/kvm/internal/logging"
 	"github.com/jetkvm/kvm/internal/network/types"
 	"github.com/jetkvm/kvm/internal/usbgadget"
 	"github.com/prometheus/client_golang/prometheus"
 	"github.com/prometheus/client_golang/prometheus/promauto"
 )
@@ -128,7 +128,7 @@
 func (c *Config) GetDisplayRotation() uint16 {
 	rotationInt, err := strconv.ParseUint(c.DisplayRotation, 10, 16)
 	if err != nil {
-		logger.Warn().Err(err).Msg("invalid display rotation, using default")
+		logging.GetSubsystemLogger("config").Warn().Err(err).Msg("invalid display rotation, using default")
 		return 270
 	}
 	return uint16(rotationInt)
@@ -138,7 +138,7 @@
 func (c *Config) SetDisplayRotation(rotation string) error {
 	_, err := strconv.ParseUint(rotation, 10, 16)
 	if err != nil {
-		logger.Warn().Err(err).Msg("invalid display rotation, using default")
+		logging.GetSubsystemLogger("config").Warn().Err(err).Msg("invalid display rotation, using default")
 		return err
 	}
 	c.DisplayRotation = rotation
@@ -224,6 +224,8 @@
 	configLock.Lock()
 	defer configLock.Unlock()
 
+	logger := logging.GetSubsystemLogger("config")
+
 	if config != nil {
 		logger.Debug().Msg("config already loaded, skipping")
 		return
@@ -272,10 +274,9 @@
 		loadedConfig.KeyboardLayout = "en-US"
 	}
 
+	logging.UpdateConfigLogLevel(loadedConfig.DefaultLogLevel)
 	config = &loadedConfig
 
-	logging.GetRootLogger().UpdateLogLevel(config.DefaultLogLevel)
-
 	configSuccess.Set(1.0)
 	configSuccessTime.SetToCurrentTime()
 
@@ -294,6 +295,7 @@
 	configLock.Lock()
 	defer configLock.Unlock()
 
+	logger := logging.GetSubsystemLogger("config")
 	logger.Trace().Str("path", path).Msg("Saving config")
 
 	// fixup old keyboard layout value