From 979b32b86c0a1b8abee980e3edb8b26e062d45c7 Mon Sep 17 00:00:00 2001 From: Marc Brooks Date: Tue, 18 Nov 2025 17:50:54 -0600 Subject: [PATCH 1/5] Enhance synctrace logging. Switched the maps to be indexed by the .Pointer (not a string) Grouped the lockCount, unlockCount ,and lastLock in an trackingEntry so we can detect unlocks of something that wasn't ever locked and excessive unlocks and also tracks the first time locked and the last unlock time. Added LogDangledLocks for debugging use. Added a panic handler to the Main so we can log out panics --- internal/sync/log.go | 154 +++++++++++++++++++++++++++------------ internal/sync/release.go | 4 + main.go | 8 ++ 3 files changed, 118 insertions(+), 48 deletions(-) diff --git a/internal/sync/log.go b/internal/sync/log.go index 36d0b29c..41937430 100644 --- a/internal/sync/log.go +++ b/internal/sync/log.go @@ -10,6 +10,7 @@ import ( "time" "github.com/jetkvm/kvm/internal/logging" + "github.com/rs/zerolog" ) @@ -47,103 +48,160 @@ func logTrack(callerSkip int) *zerolog.Logger { return &l } -func logLockTrack(i string) *zerolog.Logger { +func logLockTrack(ptr uintptr) *zerolog.Logger { l := logTrack(4). With(). - Str("index", i). + Str("ptr", fmt.Sprintf("%x", ptr)). Logger() return &l } -var ( - indexMu sync.Mutex - - lockCount map[string]int = make(map[string]int) - unlockCount map[string]int = make(map[string]int) - lastLock map[string]time.Time = make(map[string]time.Time) -) - type trackable interface { sync.Locker } -func getIndex(t trackable) string { - ptr := reflect.ValueOf(t).Pointer() - return fmt.Sprintf("%x", ptr) +type trackingEntry struct { + lockCount int + unlockCount int + firstLock time.Time + lastLock time.Time + lastUnlock time.Time } -func increaseLockCount(i string) { +var ( + indexMu sync.Mutex + tracking map[uintptr]*trackingEntry = make(map[uintptr]*trackingEntry) +) + +func getPointer(t trackable) uintptr { + return reflect.ValueOf(t).Pointer() +} + +func increaseLockCount(ptr uintptr) { indexMu.Lock() defer indexMu.Unlock() - if _, ok := lockCount[i]; !ok { - lockCount[i] = 0 - } - lockCount[i]++ - - if _, ok := lastLock[i]; !ok { - lastLock[i] = time.Now() + entry, ok := tracking[ptr] + if !ok { + entry = &trackingEntry{} + entry.firstLock = time.Now() + tracking[ptr] = entry } + entry.lockCount++ + entry.lastLock = time.Now() } -func increaseUnlockCount(i string) { +func increaseUnlockCount(ptr uintptr) { indexMu.Lock() - defer indexMu.Unlock() - if _, ok := unlockCount[i]; !ok { - unlockCount[i] = 0 + entry, ok := tracking[ptr] + if !ok { + entry = &trackingEntry{} + tracking[ptr] = entry + } + entry.unlockCount++ + entry.lastUnlock = time.Now() + delta := entry.lockCount - entry.unlockCount + indexMu.Unlock() + + if !ok { + logLockTrack(ptr).Warn().Interface("entry", entry).Msg("Unlock called without prior Lock") + } + + if delta < 0 { + logLockTrack(ptr).Warn().Interface("entry", entry).Msg("Unlock called more times than Lock") } - unlockCount[i]++ } func logLock(t trackable) { - i := getIndex(t) - increaseLockCount(i) - logLockTrack(i).Trace().Msg("locking mutex") + ptr := getPointer(t) + increaseLockCount(ptr) + logLockTrack(ptr).Trace().Msg("locking mutex") } func logUnlock(t trackable) { - i := getIndex(t) - increaseUnlockCount(i) - logLockTrack(i).Trace().Msg("unlocking mutex") + ptr := getPointer(t) + increaseUnlockCount(ptr) + logLockTrack(ptr).Trace().Msg("unlocking mutex") } func logTryLock(t trackable) { - i := getIndex(t) - logLockTrack(i).Trace().Msg("trying to lock mutex") + ptr := getPointer(t) + logLockTrack(ptr).Trace().Msg("trying to lock mutex") } func logTryLockResult(t trackable, l bool) { if !l { return } - i := getIndex(t) - increaseLockCount(i) - logLockTrack(i).Trace().Msg("locked mutex") + ptr := getPointer(t) + increaseLockCount(ptr) + logLockTrack(ptr).Trace().Msg("locked mutex") } func logRLock(t trackable) { - i := getIndex(t) - increaseLockCount(i) - logLockTrack(i).Trace().Msg("locking mutex for reading") + ptr := getPointer(t) + increaseLockCount(ptr) + logLockTrack(ptr).Trace().Msg("locking mutex for reading") } func logRUnlock(t trackable) { - i := getIndex(t) - increaseUnlockCount(i) - logLockTrack(i).Trace().Msg("unlocking mutex for reading") + ptr := getPointer(t) + increaseUnlockCount(ptr) + logLockTrack(ptr).Trace().Msg("unlocking mutex for reading") } func logTryRLock(t trackable) { - i := getIndex(t) - logLockTrack(i).Trace().Msg("trying to lock mutex for reading") + ptr := getPointer(t) + logLockTrack(ptr).Trace().Msg("trying to lock mutex for reading") } func logTryRLockResult(t trackable, l bool) { if !l { return } - i := getIndex(t) - increaseLockCount(i) - logLockTrack(i).Trace().Msg("locked mutex for reading") + ptr := getPointer(t) + increaseLockCount(ptr) + logLockTrack(ptr).Trace().Msg("locked mutex for reading") +} + +// You can all this function at any time to log any dangled locks currently tracked +// it's not an error for there to be open locks, but this can help identify any +// potential issues if called judiciously +func LogDangledLocks() { + defaultLogger.Info().Msgf("Checking %v tracked locks for dangles", len(tracking)) + + indexMu.Lock() + var issues []struct { + ptr uintptr + entry trackingEntry + } + for ptr, entry := range tracking { + if entry.lockCount != entry.unlockCount { + issues = append(issues, struct { + ptr uintptr + entry trackingEntry + }{ptr, *entry}) + } + } + indexMu.Unlock() + + defaultLogger.Info().Msgf("%v potential issues", len(issues)) + + for _, issue := range issues { + ptr := issue.ptr + entry := issue.entry + delta := entry.lockCount - entry.unlockCount + + failureType := "excess unlocks" + if delta > 0 { + failureType = "held locks" + } + + defaultLogger.Warn(). + Str("ptr", fmt.Sprintf("%x", ptr)). + Interface("entry", entry). + Int("delta", delta). + Msgf("dangled lock detected: %s", failureType) + } } diff --git a/internal/sync/release.go b/internal/sync/release.go index daec330e..8931a278 100644 --- a/internal/sync/release.go +++ b/internal/sync/release.go @@ -90,3 +90,7 @@ type Once struct { func (o *Once) Do(f func()) { o.mu.Do(f) } + +// logDangledLocks is a no-op in non-synctrace builds +func LogDangledLocks() { +} diff --git a/main.go b/main.go index d7ecc3e1..39f71123 100644 --- a/main.go +++ b/main.go @@ -16,6 +16,13 @@ var appCtx context.Context func Main() { logger.Log().Msg("JetKVM Starting Up") + defer func() { + if r := recover(); r != nil { + logger.Panic().Interface("error", r).Msg("Received panic") + panic(r) // Re-panic to crash as usual + } + }() + checkFailsafeReason() if failsafeModeActive { logger.Warn().Str("reason", failsafeModeReason).Msg("failsafe mode activated") @@ -140,6 +147,7 @@ func Main() { <-sigs logger.Log().Msg("JetKVM Shutting Down") + //if fuseServer != nil { // err := setMassStorageImage(" ") // if err != nil { From 5964077168f4edbc4952df6f1c83da061223e1b3 Mon Sep 17 00:00:00 2001 From: Marc Brooks Date: Tue, 18 Nov 2025 18:21:10 -0600 Subject: [PATCH 2/5] Switch to traceable sync for most everything --- cloud.go | 11 +++++------ config.go | 3 ++- display.go | 3 ++- failsafe.go | 3 ++- hw.go | 3 ++- internal/mdns/mdns.go | 3 ++- internal/native/native.go | 3 ++- internal/native/single.go | 2 +- internal/timesync/timesync.go | 3 ++- internal/usbgadget/hid_keyboard.go | 3 ++- internal/usbgadget/usbgadget.go | 3 ++- internal/usbgadget/utils.go | 3 ++- internal/websecure/store.go | 3 ++- native.go | 5 +++-- usb_mass_storage.go | 6 +++--- web_tls.go | 2 +- webrtc.go | 9 +++++---- 17 files changed, 40 insertions(+), 28 deletions(-) diff --git a/cloud.go b/cloud.go index dbbd3bbc..3474b9a6 100644 --- a/cloud.go +++ b/cloud.go @@ -8,18 +8,17 @@ import ( "fmt" "net/http" "net/url" - "sync" "time" + "github.com/jetkvm/kvm/internal/sync" + + "github.com/coder/websocket" "github.com/coder/websocket/wsjson" + "github.com/coreos/go-oidc/v3/oidc" + "github.com/gin-gonic/gin" "github.com/google/uuid" "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" ) diff --git a/config.go b/config.go index 5a3e7dc8..fdb4508c 100644 --- a/config.go +++ b/config.go @@ -5,12 +5,13 @@ import ( "fmt" "os" "strconv" - "sync" "github.com/jetkvm/kvm/internal/confparser" "github.com/jetkvm/kvm/internal/logging" "github.com/jetkvm/kvm/internal/network/types" + "github.com/jetkvm/kvm/internal/sync" "github.com/jetkvm/kvm/internal/usbgadget" + "github.com/prometheus/client_golang/prometheus" "github.com/prometheus/client_golang/prometheus/promauto" ) diff --git a/display.go b/display.go index 68723b59..bfb6751f 100644 --- a/display.go +++ b/display.go @@ -7,9 +7,10 @@ import ( "os" "strconv" "strings" - "sync" "time" + "github.com/jetkvm/kvm/internal/sync" + "github.com/prometheus/common/version" ) diff --git a/failsafe.go b/failsafe.go index 3c6b3d3a..ee56a494 100644 --- a/failsafe.go +++ b/failsafe.go @@ -4,7 +4,8 @@ import ( "fmt" "os" "strings" - "sync" + + "github.com/jetkvm/kvm/internal/sync" ) const ( diff --git a/hw.go b/hw.go index 7797adc1..37a19b5c 100644 --- a/hw.go +++ b/hw.go @@ -6,8 +6,9 @@ import ( "os/exec" "regexp" "strings" - "sync" "time" + + "github.com/jetkvm/kvm/internal/sync" ) func extractSerialNumber() (string, error) { diff --git a/internal/mdns/mdns.go b/internal/mdns/mdns.go index 2b954d45..bf2949e4 100644 --- a/internal/mdns/mdns.go +++ b/internal/mdns/mdns.go @@ -5,9 +5,10 @@ import ( "net" "reflect" "strings" - "sync" "github.com/jetkvm/kvm/internal/logging" + "github.com/jetkvm/kvm/internal/sync" + pion_mdns "github.com/pion/mdns/v2" "github.com/rs/zerolog" "golang.org/x/net/ipv4" diff --git a/internal/native/native.go b/internal/native/native.go index cb8761cf..792ee747 100644 --- a/internal/native/native.go +++ b/internal/native/native.go @@ -1,9 +1,10 @@ package native import ( - "sync" "time" + "github.com/jetkvm/kvm/internal/sync" + "github.com/Masterminds/semver/v3" "github.com/rs/zerolog" ) diff --git a/internal/native/single.go b/internal/native/single.go index 0782b28c..240a348e 100644 --- a/internal/native/single.go +++ b/internal/native/single.go @@ -1,6 +1,6 @@ package native -import "sync" +import "github.com/jetkvm/kvm/internal/sync" var ( instance *Native diff --git a/internal/timesync/timesync.go b/internal/timesync/timesync.go index 97cee97d..088f5359 100644 --- a/internal/timesync/timesync.go +++ b/internal/timesync/timesync.go @@ -4,10 +4,11 @@ import ( "fmt" "os" "os/exec" - "sync" "time" "github.com/jetkvm/kvm/internal/network/types" + "github.com/jetkvm/kvm/internal/sync" + "github.com/rs/zerolog" ) diff --git a/internal/usbgadget/hid_keyboard.go b/internal/usbgadget/hid_keyboard.go index 74cf76f9..f50baf5b 100644 --- a/internal/usbgadget/hid_keyboard.go +++ b/internal/usbgadget/hid_keyboard.go @@ -5,9 +5,10 @@ import ( "context" "fmt" "os" - "sync" "time" + "github.com/jetkvm/kvm/internal/sync" + "github.com/rs/xid" "github.com/rs/zerolog" ) diff --git a/internal/usbgadget/usbgadget.go b/internal/usbgadget/usbgadget.go index f01ae09d..e9d352c0 100644 --- a/internal/usbgadget/usbgadget.go +++ b/internal/usbgadget/usbgadget.go @@ -6,10 +6,11 @@ import ( "context" "os" "path" - "sync" "time" "github.com/jetkvm/kvm/internal/logging" + "github.com/jetkvm/kvm/internal/sync" + "github.com/rs/zerolog" ) diff --git a/internal/usbgadget/utils.go b/internal/usbgadget/utils.go index 85bf1579..7ec32a23 100644 --- a/internal/usbgadget/utils.go +++ b/internal/usbgadget/utils.go @@ -9,9 +9,10 @@ import ( "path/filepath" "strconv" "strings" - "sync" "time" + "github.com/jetkvm/kvm/internal/sync" + "github.com/rs/zerolog" ) diff --git a/internal/websecure/store.go b/internal/websecure/store.go index ea7911c4..aed051ca 100644 --- a/internal/websecure/store.go +++ b/internal/websecure/store.go @@ -6,7 +6,8 @@ import ( "os" "path" "strings" - "sync" + + "github.com/jetkvm/kvm/internal/sync" "github.com/rs/zerolog" ) diff --git a/native.go b/native.go index 81a0e50d..d2390265 100644 --- a/native.go +++ b/native.go @@ -2,11 +2,12 @@ package kvm import ( "os" - "sync" "time" - "github.com/Masterminds/semver/v3" "github.com/jetkvm/kvm/internal/native" + "github.com/jetkvm/kvm/internal/sync" + + "github.com/Masterminds/semver/v3" "github.com/pion/webrtc/v4/pkg/media" ) diff --git a/usb_mass_storage.go b/usb_mass_storage.go index 0f1f4b93..5f444deb 100644 --- a/usb_mass_storage.go +++ b/usb_mass_storage.go @@ -10,16 +10,16 @@ import ( "path" "path/filepath" "strings" - "sync" "syscall" "time" + "github.com/jetkvm/kvm/internal/sync" + "github.com/jetkvm/kvm/resource" + "github.com/gin-gonic/gin" "github.com/google/uuid" "github.com/pion/webrtc/v4" "github.com/psanford/httpreadat" - - "github.com/jetkvm/kvm/resource" ) func writeFile(path string, data string) error { diff --git a/web_tls.go b/web_tls.go index 41f532ea..913302d9 100644 --- a/web_tls.go +++ b/web_tls.go @@ -7,8 +7,8 @@ import ( "errors" "fmt" "net/http" - "sync" + "github.com/jetkvm/kvm/internal/sync" "github.com/jetkvm/kvm/internal/websecure" ) diff --git a/webrtc.go b/webrtc.go index 46fca2b8..6b7d1391 100644 --- a/webrtc.go +++ b/webrtc.go @@ -6,15 +6,16 @@ import ( "encoding/json" "net" "strings" - "sync" "time" + "github.com/jetkvm/kvm/internal/hidrpc" + "github.com/jetkvm/kvm/internal/logging" + "github.com/jetkvm/kvm/internal/sync" + "github.com/jetkvm/kvm/internal/usbgadget" + "github.com/coder/websocket" "github.com/coder/websocket/wsjson" "github.com/gin-gonic/gin" - "github.com/jetkvm/kvm/internal/hidrpc" - "github.com/jetkvm/kvm/internal/logging" - "github.com/jetkvm/kvm/internal/usbgadget" "github.com/pion/webrtc/v4" "github.com/rs/zerolog" ) From 8fbd4f29559a5b93981d370fa19e37eb0cbd8b78 Mon Sep 17 00:00:00 2001 From: Marc Brooks Date: Tue, 18 Nov 2025 19:15:14 -0600 Subject: [PATCH 3/5] More documentation --- DEVELOPMENT.md | 32 ++++++++++++++++++++++++++++++-- 1 file changed, 30 insertions(+), 2 deletions(-) diff --git a/DEVELOPMENT.md b/DEVELOPMENT.md index 0ab65c4f..91228f04 100644 --- a/DEVELOPMENT.md +++ b/DEVELOPMENT.md @@ -112,12 +112,16 @@ tail -f /var/log/jetkvm.log │ │ ├── cgo/ # C files for the native library (HDMI, Touchscreen, etc.) │ │ └── eez/ # EEZ Studio Project files (for Touchscreen) │ ├── network/ # Network implementation +│ ├── sync/ # Synchronization primatives with automatic logging (if synctrace enabled) │ ├── timesync/ # Time sync/NTP implementation │ ├── tzdata/ # Timezone data and generation │ ├── udhcpc/ # DHCP implementation │ ├── usbgadget/ # USB gadget │ ├── utils/ # SSH handling │ └── websecure/ # TLS certificate management +├── pkg/ # External packages that have customizations +│ ├── myip/ # Get public IP information +│ └── nmlite/ # Network link manager ├── resource/ # netboot iso and other resources ├── scripts/ # Bash shell scripts for building and deploying └── static/ # (react client build output) @@ -162,7 +166,7 @@ tail -f /var/log/jetkvm.log ```bash cd ui -npm install +npm ci ./dev_device.sh ``` @@ -195,9 +199,11 @@ ssh root@192.168.1.100 ps aux | grep jetkvm ### View live logs +The file + ```bash ssh root@192.168.1.100 -tail -f /var/log/jetkvm.log +tail -f /var/log/jetkvm* ``` ### Reset everything (if stuck) @@ -322,6 +328,28 @@ Or if you want to manually create the symlink use: mklink /d ui ..\eez\src\ui ``` +### Build is unstable even before you changed anything + +Make sure you clean up your _node_ modules and do an `npm ci` (**not** `npm i`) to ensure that you get the exact packages required by _package-lock.json_. This is especially important when switching branches! + +```bash +cd ui && rm -rf node_modules/ && npm ci && cd .. +``` + +If you are working on upgrades to the UI packages use this command to wipe the slate clean and get a new valid _package-lock.json_: + +```bash +cd ui && rm -rf node_modules/ package-lock.json && npm i && cd .. +``` + +### Device panics or becomes unresponsive + +You can also run the device-side _go_ code under a debug session to view the logs as the device is booting up and being used. To do this use the following command in your development command-line (where the IP is the JetKVM device's IP on your network) to see a very detailed `synctrace` of all mutex activity: + +```bash +./dev_deploy.sh -r --enable-sync-trace +``` + --- ## Next Steps From afca8c36429bc31f9e998243b3caffdaa13191f5 Mon Sep 17 00:00:00 2001 From: Marc Brooks Date: Tue, 18 Nov 2025 19:19:50 -0600 Subject: [PATCH 4/5] Update internal/sync/log.go Co-authored-by: Copilot <175728472+Copilot@users.noreply.github.com> --- internal/sync/log.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/internal/sync/log.go b/internal/sync/log.go index 41937430..a7894423 100644 --- a/internal/sync/log.go +++ b/internal/sync/log.go @@ -165,7 +165,7 @@ func logTryRLockResult(t trackable, l bool) { logLockTrack(ptr).Trace().Msg("locked mutex for reading") } -// You can all this function at any time to log any dangled locks currently tracked +// You can call this function at any time to log any dangled locks currently tracked // it's not an error for there to be open locks, but this can help identify any // potential issues if called judiciously func LogDangledLocks() { From f6ebdba48a7cd64e891bcea924ff8bc85abf1418 Mon Sep 17 00:00:00 2001 From: Marc Brooks Date: Tue, 18 Nov 2025 19:21:31 -0600 Subject: [PATCH 5/5] Update DEVELOPMENT.md Co-authored-by: Copilot <175728472+Copilot@users.noreply.github.com> --- DEVELOPMENT.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/DEVELOPMENT.md b/DEVELOPMENT.md index 91228f04..687a6266 100644 --- a/DEVELOPMENT.md +++ b/DEVELOPMENT.md @@ -199,7 +199,7 @@ ssh root@192.168.1.100 ps aux | grep jetkvm ### View live logs -The file +The file `/var/log/jetkvm*` contains the JetKVM logs. You can view live logs with: ```bash ssh root@192.168.1.100