From 979b32b86c0a1b8abee980e3edb8b26e062d45c7 Mon Sep 17 00:00:00 2001 From: Marc Brooks Date: Tue, 18 Nov 2025 17:50:54 -0600 Subject: [PATCH] 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 {