diff --git a/go.mod b/go.mod index 962c3a1b..d07ba239 100644 --- a/go.mod +++ b/go.mod @@ -12,6 +12,7 @@ require ( github.com/gin-contrib/logger v1.2.6 github.com/gin-gonic/gin v1.10.1 github.com/go-co-op/gocron/v2 v2.16.5 + github.com/google/flatbuffers v25.2.10+incompatible github.com/google/uuid v1.6.0 github.com/guregu/null/v6 v6.0.0 github.com/gwatts/rootcerts v0.0.0-20250901182336-dc5ae18bd79f @@ -23,6 +24,7 @@ require ( github.com/prometheus/common v0.66.0 github.com/prometheus/procfs v0.17.0 github.com/psanford/httpreadat v0.1.0 + github.com/rs/xid v1.6.0 github.com/rs/zerolog v1.34.0 github.com/sourcegraph/tf-dag v0.2.2-0.20250131204052-3e8ff1477b4f github.com/stretchr/testify v1.11.1 diff --git a/go.sum b/go.sum index e19fa9e6..57576a3a 100644 --- a/go.sum +++ b/go.sum @@ -53,6 +53,8 @@ github.com/go-playground/validator/v10 v10.26.0/go.mod h1:I5QpIEbmr8On7W0TktmJAu github.com/goccy/go-json v0.10.5 h1:Fq85nIqj+gXn/S5ahsiTlK3TmC85qgirsdTP/+DeaC4= github.com/goccy/go-json v0.10.5/go.mod h1:oq7eo15ShAhp70Anwd5lgX2pLfOS3QCiwU/PULtXL6M= github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA= +github.com/google/flatbuffers v25.2.10+incompatible h1:F3vclr7C3HpB1k9mxCGRMXq6FdUalZ6H/pNX4FP1v0Q= +github.com/google/flatbuffers v25.2.10+incompatible/go.mod h1:1AeVuKshWv4vARoZatz6mlQ0JxURH0Kv5+zNeJKJCa8= github.com/google/go-cmp v0.7.0 h1:wk8382ETsv4JYUZwIsn6YpYiWiBsYLSJiTsyBybVuN8= github.com/google/go-cmp v0.7.0/go.mod h1:pXiqmnSA92OHEEa9HXL2W4E7lf9JzCmGVUdgjX3N/iU= github.com/google/gofuzz v1.0.0/go.mod h1:dBl0BpW6vV/+mYPU4Po3pmUjxk6FQPldtuIdl/M65Eg= @@ -152,6 +154,7 @@ github.com/robfig/cron/v3 v3.0.1 h1:WdRxkvbJztn8LMz/QEvLN5sBU+xKpSqwwUO1Pjr4qDs= github.com/robfig/cron/v3 v3.0.1/go.mod h1:eQICP3HwyT7UooqI/z+Ov+PtYAWygg1TEWWzGIFLtro= github.com/rogpeppe/go-internal v1.14.1 h1:UQB4HGPB6osV0SQTLymcB4TgvyWu6ZyliaW0tI/otEQ= github.com/rogpeppe/go-internal v1.14.1/go.mod h1:MaRKkUm5W0goXpeCfT7UZI6fk/L7L7so1lCWt35ZSgc= +github.com/rs/xid v1.6.0 h1:fV591PaemRlL6JfRxGDEPl69wICngIQ3shQtzfy2gxU= github.com/rs/xid v1.6.0/go.mod h1:7XoLgs4eV+QndskICGsho+ADou8ySMSjJKDIan90Nz0= github.com/rs/zerolog v1.34.0 h1:k43nTLIwcTVQAncfCw4KZ2VY6ukYoZaBPNOE8txlOeY= github.com/rs/zerolog v1.34.0/go.mod h1:bJsvje4Z08ROH4Nhs5iH600c3IkWhwp44iRc54W6wYQ= diff --git a/hidrpc.go b/hidrpc.go index a81e115a..46a8ced7 100644 --- a/hidrpc.go +++ b/hidrpc.go @@ -8,6 +8,7 @@ import ( "github.com/jetkvm/kvm/internal/hidrpc" "github.com/jetkvm/kvm/internal/usbgadget" + "github.com/rs/zerolog" ) func handleHidRPCMessage(message hidrpc.Message, session *Session) { @@ -87,7 +88,9 @@ func onHidMessage(msg hidQueueMessage, session *Session) { return } - scopedLogger = scopedLogger.With().Str("descr", message.String()).Logger() + if scopedLogger.GetLevel() <= zerolog.DebugLevel { + scopedLogger = scopedLogger.With().Str("descr", message.String()).Logger() + } t := time.Now() @@ -184,8 +187,10 @@ func (s *Session) reportHidRPCKeyboardLedState(state usbgadget.KeyboardState) { func (s *Session) reportHidRPCKeysDownState(state usbgadget.KeysDownState) { if !s.hidRPCAvailable { + usbLogger.Debug().Interface("state", state).Msg("reporting keys down state") writeJSONRPCEvent("keysDownState", state, s) } + usbLogger.Debug().Interface("state", state).Msg("reporting keys down state, calling reportHidRPC") reportHidRPC(state, s) } diff --git a/internal/usbgadget/hid_keyboard.go b/internal/usbgadget/hid_keyboard.go index 76e5a125..53e232c0 100644 --- a/internal/usbgadget/hid_keyboard.go +++ b/internal/usbgadget/hid_keyboard.go @@ -6,6 +6,9 @@ import ( "fmt" "os" "time" + + "github.com/rs/xid" + "github.com/rs/zerolog" ) var keyboardConfig = gadgetConfigItem{ @@ -188,7 +191,7 @@ func (u *UsbGadget) scheduleAutoRelease(key byte) { } u.kbdAutoReleaseTimer = time.AfterFunc(autoReleaseKeyboardInterval, func() { - u.performAutoRelease(key) + u.performAutoRelease() }) } @@ -216,10 +219,12 @@ func (u *UsbGadget) DelayAutoRelease() { u.log.Trace().Msg("auto-release timer reset") } -func (u *UsbGadget) performAutoRelease(key byte) { +func (u *UsbGadget) performAutoRelease() { u.log.Trace().Msg("performing autoRelease") u.kbdAutoReleaseLock.Lock() - defer unlockWithLog(&u.kbdAutoReleaseLock, u.log, "autoRelease performed") + defer unlockWithLog(&u.kbdAutoReleaseLock, u.log, "autoRelease unlocked") + + key := u.kbdAutoReleaseLastKey select { case <-u.keyboardStateCtx.Done(): @@ -228,7 +233,8 @@ func (u *UsbGadget) performAutoRelease(key byte) { } // we just reset the keyboard state to 0 no matter what - _, err := u.keypressReport(0, false, false) + u.log.Trace().Uint8("key", key).Msg("auto-releasing keyboard key") + _, err := u.keypressReport(key, false, false) if err != nil { u.log.Warn().Uint8("key", key).Msg("failed to auto-release keyboard key") } @@ -399,12 +405,20 @@ var KeyCodeToMaskMap = map[byte]byte{ func (u *UsbGadget) keypressReportNonThreadSafe(key byte, press bool, autoRelease bool) (KeysDownState, error) { defer u.resetUserInputTime() + l := u.log.With().Uint8("key", key).Bool("press", press).Bool("autoRelease", autoRelease).Logger() + if l.GetLevel() <= zerolog.DebugLevel { + requestID := xid.New() + l = l.With().Str("requestID", requestID.String()).Logger() + } + // IMPORTANT: This code parallels the logic in the kernel's hid-gadget driver // for handling key presses and releases. It ensures that the USB gadget // behaves similarly to a real USB HID keyboard. This logic is paralleled // in the client/browser-side code in useKeyboard.ts so make sure to keep // them in sync. - var state = u.keysDownState + var state = u.GetKeysDownState() + l.Trace().Interface("state", state).Msg("got keys down state") + modifier := state.Modifier keys := append([]byte(nil), state.Keys...) @@ -444,37 +458,45 @@ func (u *UsbGadget) keypressReportNonThreadSafe(key byte, press bool, autoReleas // If we reach here it means we didn't find an empty slot or the key in the buffer if overrun { if press { - u.log.Error().Uint8("key", key).Msg("keyboard buffer overflow, key not added") + l.Error().Msg("keyboard buffer overflow, key not added") // Fill all key slots with ErrorRollOver (0x01) to indicate overflow for i := range keys { keys[i] = hidErrorRollOver } } else { // If we are releasing a key, and we didn't find it in a slot, who cares? - u.log.Warn().Uint8("key", key).Msg("key not found in buffer, nothing to release") + l.Warn().Msg("key not found in buffer, nothing to release") } } } + if l.GetLevel() <= zerolog.DebugLevel { + l = l.With().Uint8("modifier", modifier).Uints8("keys", keys).Logger() + } + + l.Trace().Msg("writing keypress report to hidg0") + err := u.keyboardWriteHidFile(modifier, keys) if err != nil { - u.log.Warn().Uint8("modifier", modifier).Uints8("keys", keys).Msg("Could not write keypress report to hidg0") + l.Warn().Msg("Could not write keypress report to hidg0") } + l.Trace().Msg("keypress report written to hidg0") + if press { { - u.log.Trace().Msg("acquiring kbdAutoReleaseLock to update last key") + l.Trace().Msg("acquiring kbdAutoReleaseLock to update last key") u.kbdAutoReleaseLock.Lock() u.kbdAutoReleaseLastKey = key unlockWithLog(&u.kbdAutoReleaseLock, u.log, "last key updated") } if autoRelease { - u.cancelAutoRelease() + u.scheduleAutoRelease(key) } } else { if autoRelease { - u.scheduleAutoRelease(key) + u.cancelAutoRelease() } }