More cleanup

Author: IDisposable

block_device.go

@@ -9,6 +9,7 @@ import (
 
 	"github.com/jetkvm/kvm/internal/logging"
 	"github.com/pojntfx/go-nbd/pkg/server"
+	"github.com/rs/zerolog"
 )
 
 type remoteImageBackend struct {
@@ -68,10 +69,13 @@ func NewNBDDevice() *NBDDevice {
 	return &NBDDevice{}
 }
 
-func (d *NBDDevice) getLogger() *logging.Context {
-	return logging.GetSubsystemLogger("nbd").
+func (d *NBDDevice) getLogger() *zerolog.Logger {
+	logger := logging.GetSubsystemLogger("nbd").
+		With().
 		Str("socket_path", nbdSocketPath).
-		Str("device_path", nbdDevicePath)
+		Str("device_path", nbdDevicePath).
+		Logger()
+	return &logger
 }
 
 func (d *NBDDevice) Start() error {

cloud.go

@@ -14,6 +14,7 @@ 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"
 
@@ -324,13 +325,13 @@ func runWebsocketClient() error {
 	header.Set("Authorization", "Bearer "+config.CloudToken)
 	dialCtx, cancelDial := context.WithTimeout(context.Background(), CloudWebSocketConnectTimeout)
 
-	logger := logging.GetSubsystemLogger("websocket").Str("source", wsURL.Host).Str("sourceType", "cloud")
+	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 {
-			logger.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()
@@ -357,8 +358,7 @@ func runWebsocketClient() error {
 			Msg("no connection id received from the server, generating a new one")
 	}
 
-	logger = logger.With().Str("connectionID", connectionId)
-
+	logger = logger.With().Str("connectionID", connectionId).Logger()
 	cloudLogger := logging.GetSubsystemLogger("cloud")
 
 	// if the context is canceled, we don't want to return an error

failsafe.go

@@ -103,7 +103,7 @@ func notifyFailsafeMode(session *Session) {
 
 	logging.GetSubsystemLogger("failsafe").Info().Str("reason", failsafeModeReason).Msg("sending failsafe mode notification")
 
-	writeJSONRPCEvent("failsafeMode", FailsafeModeNotification{
+	go writeJSONRPCEvent("failsafeMode", FailsafeModeNotification{
 		Active: true,
 		Reason: failsafeModeReason,
 	}, session)

hidrpc.go

@@ -34,6 +34,7 @@ func handleHidRPCMessage(message hidrpc.Message, session *Session) error {
 }
 
 func handleHidRPCHandshake(session *Session) error {
+	hidrpc.GetHidRpcLogger().Debug().Msg("handling handshake")
 	message, err := hidrpc.NewHandshakeMessage().Marshal()
 	if err != nil {
 		return err
@@ -50,6 +51,7 @@ func handleKeyboardMacro(message hidrpc.Message) error {
 	if err != nil {
 		return err
 	}
+	hidrpc.GetHidRpcLogger().Debug().Interface("keyboardMacroReport", keyboardMacroReport).Msg("handling keyboard macro")
 	return rpcExecuteKeyboardMacro(keyboardMacroReport.Steps)
 }
 
@@ -58,6 +60,7 @@ func handleMouseReport(message hidrpc.Message) error {
 	if err != nil {
 		return err
 	}
+	hidrpc.GetHidRpcLogger().Debug().Interface("mouseReport", mouseReport).Msg("handling relative mouse")
 	return rpcRelMouseReport(mouseReport.DX, mouseReport.DY, mouseReport.Button)
 }
 
@@ -66,37 +69,31 @@ func handlePointerReport(message hidrpc.Message) error {
 	if err != nil {
 		return err
 	}
+	hidrpc.GetHidRpcLogger().Debug().Interface("pointerReport", pointerReport).Msg("handling absolute pointer")
 	return rpcAbsMouseReport(pointerReport.X, pointerReport.Y, pointerReport.Button)
 }
 
-func onHidMessage(msg hidQueueMessage, session *Session, queueContext *logging.Context) {
-	logger := queueContext.With().Str("channel", msg.channel)
+func onHidMessage(msg hidQueueMessage, session *Session, index int) {
+	logger := hidrpc.GetHidRpcLogger().With().Int("queueIndex", index).Str("channel", msg.channel).Logger()
 	data := msg.Data
 
-	if logger.IsDebugLevel() {
-		logger = logger.Object("data", utils.ByteSlice(data))
+	if logging.IsTraceLevel(&logger) {
+		logger.Trace().Object("data", utils.ByteSlice(data)).Msg("HID RPC message received")
 	}
 
-	logger.Debug().Msg("HID RPC message received")
-
 	if len(data) < 1 {
-		logger.Int("length", len(data)).Warn().Msg("received empty data in HID RPC message handler")
+		logger.Warn().Int("length", len(data)).Msg("received empty data in HID RPC message handler")
 		return
 	}
 
 	var message hidrpc.Message
 
 	if err := hidrpc.Unmarshal(data, &message); err != nil {
-		logger.Err(err).Warn().Msg("failed to unmarshal HID RPC message")
+		logger.Warn().Err(err).Msg("failed to unmarshal HID RPC message")
 		return
 	}
 
-	if logger.IsDebugLevel() {
-		logger = logger.Str("message", message.String())
-	}
-
 	t := time.Now()
-
 	r := make(chan interface{})
 	go func() {
 		r <- handleHidRPCMessage(message, session)
@@ -170,9 +167,7 @@ func handleHidRPCKeypressKeepAlive(session *Session) error {
 }
 
 func handleHidRPCKeyboardInput(message hidrpc.Message) error {
-	logger := hidrpc.GetHidRpcLoggingContext().
-		With().
-		Interface("message", message)
+	logger := hidrpc.GetHidRpcLogger().With().Interface("message", message).Logger()
 
 	switch message.Type() {
 	case hidrpc.TypeKeypressReport:
@@ -181,24 +176,23 @@ func handleHidRPCKeyboardInput(message hidrpc.Message) error {
 			logger.Warn().Err(err).Msg("failed to get keypress report")
 			return err
 		}
+		logger.Debug().Interface("keypressReport", keypressReport).Msg("handling key press")
 		return rpcKeypressReport(keypressReport.Key, keypressReport.Press)
 	case hidrpc.TypeKeyboardReport:
 		keyboardReport, err := message.KeyboardReport()
 		if err != nil {
 			logger.Warn().Err(err).Msg("failed to get keyboard report")
 			return err
 		}
+		logger.Debug().Interface("keyboardReport", keyboardReport).Msg("handling keyboard")
 		return rpcKeyboardReport(keyboardReport.Modifier, keyboardReport.Keys)
 	}
 
 	return fmt.Errorf("unknown HID RPC message type: %d", message.Type())
 }
 
 func reportHidRPC(params any, session *Session) {
-	logger := hidrpc.GetHidRpcLoggingContext().
-		With().
-		Interface("params", params).
-		Interface("session", session)
+	logger := hidrpc.GetHidRpcLogger().With().Interface("params", params).Logger()
 
 	if session == nil {
 		logger.Warn().Msg("session is nil, skipping reportHidRPC")
@@ -229,22 +223,33 @@ func reportHidRPC(params any, session *Session) {
 		err = fmt.Errorf("unknown HID RPC message type: %T", params)
 	}
 
-	logger = logger.Bytes("message", message)
+	logger = logger.With().Type("type", params).Logger()
 
 	if err != nil || message == nil {
 		logger.Warn().Err(err).Msg("failed to marshal HID RPC message")
 		return
 	}
 
 	// fire and forget...
-	logger.Debug().Msg("sending HID RPC report")
 	go func() {
-		if err := session.HidChannel.Send(message); err != nil {
-			if errors.Is(err, io.ErrClosedPipe) {
-				logger.Debug().Err(err).Msg("HID RPC channel closed, skipping reportHidRPC")
-				return
+		t := time.Now()
+		r := make(chan interface{})
+		go func() {
+			logger.Trace().Msg("sending HID RPC report")
+			r <- session.HidChannel.Send(message)
+		}()
+		select {
+		case <-time.After(1 * time.Second):
+			logger.Warn().Msg("HID RPC report took too long")
+		case err := <-r:
+			logger.Debug().Dur("duration", time.Since(t)).Msg("HID RPC report sent")
+			if err != nil {
+				if errors.Is(err.(error), io.ErrClosedPipe) {
+					logger.Warn().Err(err.(error)).Msg("HID RPC channel closed, skipping reportHidRPC")
+					return
+				}
+				logger.Warn().Err(err.(error)).Msg("failed to send HID RPC report")
 			}
-			logger.Warn().Err(err).Msg("failed to send HID RPC message")
 		}
 	}()
 }

hw.go

@@ -92,7 +92,7 @@ func GetDefaultHostname() string {
 }
 
 func runWatchdog() {
-	watchdogLogger := logging.GetSubsystemLogger("watchdog")
+	watchdogLogger := logging.GetSubsystemLogger("hw").With().Str("subcomponent", "watchdog").Logger()
 
 	file, err := os.OpenFile("/dev/watchdog", os.O_WRONLY, 0)
 	if err != nil {

internal/hidrpc/hidrpc.go

@@ -7,7 +7,8 @@ import (
 )
 
 const (
-	Version byte = 0x01 // Version of the HID RPC protocol
+	Version       byte = 0x01 // Version of the HID RPC protocol
+	MaximumQueues int  = 4    // Maximum number of HID RPC queues
 )
 
 // GetQueueIndex returns the index of the queue to which the message should be enqueued.

internal/hidrpc/log.go

@@ -2,8 +2,9 @@ package hidrpc
 
 import (
 	"github.com/jetkvm/kvm/internal/logging"
+	"github.com/rs/zerolog"
 )
 
-func GetHidRpcLoggingContext() *logging.Context {
+func GetHidRpcLogger() *zerolog.Logger {
 	return logging.GetSubsystemLogger("hidrpc")
 }

internal/hidrpc/message.go

@@ -31,9 +31,9 @@ type Message struct {
 	d []byte
 }
 
-func (m *Message) MarshalZerologObject(e *zerolog.Event) {
-	e.Uint8("type", uint8(m.t))
-	e.Bytes("payload", m.d)
+func (m Message) MarshalZerologObject(e *zerolog.Event) {
+	e.Uint8("Type", uint8(m.t))
+	e.Bytes("Payload", m.d)
 }
 
 // Marshal marshals the message to a byte array.
@@ -98,8 +98,8 @@ type KeypressReport struct {
 	Press bool
 }
 
-func (k *KeypressReport) MarshalZerologObject(e *zerolog.Event) {
-	e.Hex("Modifier", []byte{k.Key})
+func (k KeypressReport) MarshalZerologObject(e *zerolog.Event) {
+	e.Hex("Key", []byte{k.Key})
 	e.Bool("Press", k.Press)
 }
 
@@ -121,7 +121,7 @@ type KeyboardReport struct {
 	Keys     []byte // 6 bytes: HidKeyBufferSize
 }
 
-func (k *KeyboardReport) MarshalZerologObject(e *zerolog.Event) {
+func (k KeyboardReport) MarshalZerologObject(e *zerolog.Event) {
 	e.Hex("Modifier", []byte{k.Modifier})
 	e.Hex("Keys", k.Keys)
 }
@@ -145,7 +145,7 @@ type KeyboardMacroStep struct {
 	Delay    uint16 // 2 bytes
 }
 
-func (s *KeyboardMacroStep) MarshalZerologObject(e *zerolog.Event) {
+func (s KeyboardMacroStep) MarshalZerologObject(e *zerolog.Event) {
 	e.Hex("Modifier", []byte{s.Modifier})
 	e.Hex("Keys", s.Keys)
 	e.Uint16("Delay", s.Delay)