Enhance synctrace logging

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 <YOUR_DEVICE_IP>
 ```
 
@@ -195,9 +199,11 @@ ssh [email protected] ps aux | grep jetkvm
 
 ### View live logs
 
+The file `/var/log/jetkvm*` contains the JetKVM logs. You can view live logs with:
+
 ```bash
 ssh [email protected]
-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 <IP> --enable-sync-trace
+```
+
 ---
 
 ## Next Steps

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"
 )
 

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"
 )

display.go

@@ -7,9 +7,10 @@ import (
 	"os"
 	"strconv"
 	"strings"
-	"sync"
 	"time"
 
+	"github.com/jetkvm/kvm/internal/sync"
+
 	"github.com/prometheus/common/version"
 )
 

failsafe.go

@@ -4,7 +4,8 @@ import (
 	"fmt"
 	"os"
 	"strings"
-	"sync"
+
+	"github.com/jetkvm/kvm/internal/sync"
 )
 
 const (

hw.go

@@ -6,8 +6,9 @@ import (
 	"os/exec"
 	"regexp"
 	"strings"
-	"sync"
 	"time"
+
+	"github.com/jetkvm/kvm/internal/sync"
 )
 
 func extractSerialNumber() (string, error) {

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"

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"
 )

internal/native/single.go

@@ -1,6 +1,6 @@
 package native
 
-import "sync"
+import "github.com/jetkvm/kvm/internal/sync"
 
 var (
 	instance     *Native

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 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() {
+	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)
+	}
 }

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() {
+}