Enhance synctrace logging (#980)

* 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

* Switch to traceable sync for most everything

* More documentation

* Update internal/sync/log.go

* Update DEVELOPMENT.md

* Resolve merge issue.

* Applied review comments

* Restore --enable-sync-trace option.

* Use WithLevel so we can re-panic as desired

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 root@192.168.1.100 ps aux | grep jetkvm
 
 ### View live logs
 
+The file `/var/log/jetkvm*` contains the JetKVM logs. You can view live logs with:
+
 ```bash
 ssh root@192.168.1.100
-tail -f /var/log/jetkvm.log
+tail -f /var/log/jetkvm*
 ```
 
 ### Reset everything (if stuck)
@@ -328,6 +334,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

@@ -6,12 +6,13 @@ import (
 	"os"
 	"strconv"
 	"strings"
-	"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,9 +4,9 @@ import (
 	"io"
 	"os"
 	"strings"
-	"sync"
 
 	"github.com/jetkvm/kvm/internal/supervisor"
+	"github.com/jetkvm/kvm/internal/sync"
 )
 
 const (

hw.go

@@ -6,10 +6,10 @@ import (
 	"os/exec"
 	"regexp"
 	"strings"
-	"sync"
 	"time"
 
 	"github.com/jetkvm/kvm/internal/ota"
+	"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

@@ -2,9 +2,10 @@ package native
 
 import (
 	"os"
-	"sync"
 	"time"
 
+	"github.com/jetkvm/kvm/internal/sync"
+
 	"github.com/Masterminds/semver/v3"
 	"github.com/jetkvm/kvm/internal/diagnostics"
 	"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,158 @@ 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 any prior Lock")
+	} else 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 is 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() {
+}

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

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

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

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

internal/websecure/store.go

@@ -6,7 +6,8 @@ import (
 	"os"
 	"path"
 	"strings"
-	"sync"
+
+	"github.com/jetkvm/kvm/internal/sync"
 
 	"github.com/rs/zerolog"
 )

main.go

@@ -9,9 +9,11 @@ import (
 	"syscall"
 	"time"
 
+	"github.com/jetkvm/kvm/internal/ota"
+
 	"github.com/erikdubbelboer/gspt"
 	"github.com/gwatts/rootcerts"
-	"github.com/jetkvm/kvm/internal/ota"
+	"github.com/rs/zerolog"
 )
 
 var appCtx context.Context
@@ -30,6 +32,13 @@ func Main() {
 
 	logger.Log().Msg("JetKVM Starting Up")
 
+	defer func() {
+		if r := recover(); r != nil {
+			logger.WithLevel(zerolog.PanicLevel).Interface("error", r).Msg("Received panic")
+			panic(r) // Re-panic to crash as usual
+		}
+	}()
+
 	checkFailsafeReason()
 	if failsafeModeActive {
 		procPrefix = "jetkvm: [app+failsafe]"
@@ -170,6 +179,7 @@ func Main() {
 	<-sigs
 
 	logger.Log().Msg("JetKVM Shutting Down")
+
 	//if fuseServer != nil {
 	//	err := setMassStorageImage(" ")
 	//	if err != nil {

native.go

@@ -2,12 +2,13 @@ package kvm
 
 import (
 	"os"
-	"sync"
 	"time"
 
-	"github.com/Masterminds/semver/v3"
 	"github.com/jetkvm/kvm/internal/diagnostics"
 	"github.com/jetkvm/kvm/internal/native"
+	"github.com/jetkvm/kvm/internal/sync"
+
+	"github.com/Masterminds/semver/v3"
 	"github.com/pion/webrtc/v4/pkg/media"
 )
 

scripts/dev_deploy.sh

@@ -105,6 +105,11 @@ while [[ $# -gt 0 ]]; do
             RESET_USB_HID_DEVICE=true
             shift
             ;;
+        --enable-sync-trace)
+            ENABLE_SYNC_TRACE=1
+            LOG_TRACE_SCOPES="${LOG_TRACE_SCOPES},synctrace"
+            shift
+            ;;
         --disable-docker)
             BUILD_IN_DOCKER=false
             shift
@@ -142,6 +147,12 @@ while [[ $# -gt 0 ]]; do
     esac
 done
 
+if [ "$ENABLE_SYNC_TRACE" = 1 ]; then
+    if [[ ! "$LOG_TRACE_SCOPES" =~ synctrace ]]; then
+        LOG_TRACE_SCOPES="${LOG_TRACE_SCOPES},synctrace"
+    fi
+fi
+
 source ${SCRIPT_PATH}/build_utils.sh
 
 # Verify required parameters

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 {

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

webrtc.go

@@ -6,16 +6,17 @@ import (
 	"encoding/json"
 	"net"
 	"strings"
-	"sync"
 	"time"
 
+	"github.com/jetkvm/kvm/internal/diagnostics"
+	"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/diagnostics"
-	"github.com/jetkvm/kvm/internal/hidrpc"
-	"github.com/jetkvm/kvm/internal/logging"
-	"github.com/jetkvm/kvm/internal/usbgadget"
 	"github.com/pion/ice/v4"
 	"github.com/pion/webrtc/v4"
 	"github.com/rs/zerolog"