Switched to fluent logging contexts

Add missing types for enhancing context
Also cleaned up the syntax to be more compact
Expose the zerolog.Event for levels
Ported synctrace and timesync

Author: IDisposable

cloud.go

@@ -325,7 +325,8 @@ func runWebsocketClient() error {
 	header.Set("Authorization", "Bearer "+config.CloudToken)
 	dialCtx, cancelDial := context.WithTimeout(context.Background(), CloudWebSocketConnectTimeout)
 
-	l := logging.GetSubsystemLogger("websocket").With().
+	l := logging.GetSubsystemLogger("websocket").
+		With().
 		Str("source", wsURL.Host).
 		Str("sourceType", "cloud").
 		Logger()
@@ -457,7 +458,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})

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 (

hidrpc.go

@@ -9,7 +9,7 @@ import (
 	"github.com/jetkvm/kvm/internal/hidrpc"
 	"github.com/jetkvm/kvm/internal/logging"
 	"github.com/jetkvm/kvm/internal/usbgadget"
-	"github.com/rs/zerolog"
+	"github.com/jetkvm/kvm/internal/utils"
 )
 
 func handleHidRPCMessage(message hidrpc.Message, session *Session) error {
@@ -69,30 +69,30 @@ func handlePointerReport(message hidrpc.Message) error {
 	return rpcAbsMouseReport(pointerReport.X, pointerReport.Y, pointerReport.Button)
 }
 
-func onHidMessage(msg hidQueueMessage, session *Session) {
+func onHidMessage(msg hidQueueMessage, session *Session, queueContext *logging.Context) {
+	logger := queueContext.With().Str("channel", msg.channel)
 	data := msg.Data
 
-	scopedLogger := logging.GetSubsystemLogger("hidrpc").
-		With().
-		Str("channel", msg.channel).
-		Bytes("data", data).
-		Logger()
-	scopedLogger.Debug().Msg("HID RPC message received")
+	if logger.IsDebugLevel() {
+		logger = logger.Object("data", utils.ByteSlice(data))
+	}
+
+	logger.Debug().Msg("HID RPC message received")
 
 	if len(data) < 1 {
-		scopedLogger.Warn().Int("length", len(data)).Msg("received empty data in HID RPC message handler")
+		logger.Int("length", len(data)).Warn().Msg("received empty data in HID RPC message handler")
 		return
 	}
 
 	var message hidrpc.Message
 
 	if err := hidrpc.Unmarshal(data, &message); err != nil {
-		scopedLogger.Warn().Err(err).Msg("failed to unmarshal HID RPC message")
+		logger.Err(err).Warn().Msg("failed to unmarshal HID RPC message")
 		return
 	}
 
-	if scopedLogger.GetLevel() <= zerolog.DebugLevel {
-		scopedLogger = scopedLogger.With().Str("descr", message.String()).Logger()
+	if logger.IsDebugLevel() {
+		logger = logger.Str("message", message.String())
 	}
 
 	t := time.Now()
@@ -103,11 +103,11 @@ func onHidMessage(msg hidQueueMessage, session *Session) {
 	}()
 	select {
 	case <-time.After(1 * time.Second):
-		scopedLogger.Warn().Msg("HID RPC message timed out")
+		logger.Warn().Msg("HID RPC message took too long")
 	case err := <-r:
-		scopedLogger.Debug().Dur("duration", time.Since(t)).Msg("HID RPC message handled")
+		logger.Debug().Dur("duration", time.Since(t)).Msg("HID RPC message handled")
 		if err != nil {
-			scopedLogger.Warn().Err(err.(error)).Msg("failed to handle HID RPC message")
+			logger.Warn().Err(err.(error)).Msg("failed to handle HID RPC message")
 		}
 	}
 }
@@ -117,12 +117,10 @@ func onHidMessage(msg hidQueueMessage, session *Session) {
 // macOS default: 15 * 15 = 225ms https://discussions.apple.com/thread/1316947?sortBy=rank
 // Linux default: 250ms https://man.archlinux.org/man/kbdrate.8.en
 // Windows default: 1s `HKEY_CURRENT_USER\Control Panel\Accessibility\Keyboard Response\AutoRepeatDelay`
-
 const expectedRate = 50 * time.Millisecond       // expected keepalive interval
 const maxLateness = 50 * time.Millisecond        // max jitter we'll tolerate OR jitter budget
 const baseExtension = expectedRate + maxLateness // 100ms extension on perfect tick
-
-const maxStaleness = 225 * time.Millisecond // discard ancient packets outright
+const maxStaleness = 225 * time.Millisecond      // discard ancient packets outright
 
 func handleHidRPCKeypressKeepAlive(session *Session) error {
 	session.keepAliveJitterLock.Lock()
@@ -172,19 +170,23 @@ func handleHidRPCKeypressKeepAlive(session *Session) error {
 }
 
 func handleHidRPCKeyboardInput(message hidrpc.Message) error {
-	context := logging.GetSubsystemLogger("hidrpc").With().Interface("message", message)
+	logger := hidrpc.GetHidRpcLoggingContext().
+		With().
+		Interface("message", message)
 
 	switch message.Type() {
 	case hidrpc.TypeKeypressReport:
 		keypressReport, err := message.KeypressReport()
 		if err != nil {
-			return logging.LogWarnE(context, err, "failed to get keypress report")
+			logger.Warn().Err(err).Msg("failed to get keypress report")
+			return err
 		}
 		return rpcKeypressReport(keypressReport.Key, keypressReport.Press)
 	case hidrpc.TypeKeyboardReport:
 		keyboardReport, err := message.KeyboardReport()
 		if err != nil {
-			return logging.LogWarnE(context, err, "failed to get keyboard report")
+			logger.Warn().Err(err).Msg("failed to get keyboard report")
+			return err
 		}
 		return rpcKeyboardReport(keyboardReport.Modifier, keyboardReport.Keys)
 	}
@@ -193,7 +195,10 @@ func handleHidRPCKeyboardInput(message hidrpc.Message) error {
 }
 
 func reportHidRPC(params any, session *Session) {
-	logger := logging.GetSubsystemLogger("hidrpc")
+	logger := hidrpc.GetHidRpcLoggingContext().
+		With().
+		Interface("params", params).
+		Interface("session", session)
 
 	if session == nil {
 		logger.Warn().Msg("session is nil, skipping reportHidRPC")
@@ -224,15 +229,16 @@ func reportHidRPC(params any, session *Session) {
 		err = fmt.Errorf("unknown HID RPC message type: %T", params)
 	}
 
+	logger = logger.Bytes("message", message)
+
 	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() {
-		logger.Debug().Bytes("message", message).Msg("executing keyboard macro")
-
 		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")

internal/hidrpc/hidrpc.go

@@ -39,19 +39,6 @@ func Unmarshal(data []byte, message *Message) error {
 	return nil
 }
 
-// Marshal marshals the HID RPC message to the data.
-func Marshal(message *Message) ([]byte, error) {
-	if message.t == 0 {
-		return nil, fmt.Errorf("invalid message type: %d", message.t)
-	}
-
-	data := make([]byte, len(message.d)+1)
-	data[0] = byte(message.t)
-	copy(data[1:], message.d)
-
-	return data, nil
-}
-
 // NewHandshakeMessage creates a new handshake message.
 func NewHandshakeMessage() *Message {
 	return &Message{

internal/hidrpc/log.go

@@ -0,0 +1,9 @@
+package hidrpc
+
+import (
+	"github.com/jetkvm/kvm/internal/logging"
+)
+
+func GetHidRpcLoggingContext() *logging.Context {
+	return logging.NewContext(logging.GetSubsystemLogger("hidrpc"))
+}

internal/hidrpc/message.go

@@ -31,9 +31,22 @@ type Message struct {
 	d []byte
 }
 
+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.
 func (m *Message) Marshal() ([]byte, error) {
-	return Marshal(m)
+	if m.t == 0 {
+		return nil, fmt.Errorf("invalid message type: %d", m.t)
+	}
+
+	data := make([]byte, len(m.d)+1)
+	data[0] = byte(m.t)
+	copy(data[1:], m.d)
+
+	return data, nil
 }
 
 func (m *Message) Type() MessageType {
@@ -85,7 +98,7 @@ type KeypressReport struct {
 	Press bool
 }
 
-func (k KeypressReport) MarshalZerologObject(e *zerolog.Event) {
+func (k *KeypressReport) MarshalZerologObject(e *zerolog.Event) {
 	e.Hex("Modifier", []byte{k.Key})
 	e.Bool("Press", k.Press)
 }
@@ -108,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)
 }
@@ -132,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)