use sync trace to track mutexes to make deadlock analysis easier

.vscode/settings.json

@@ -3,5 +3,11 @@
     "cva",
     "cx"
   ],
+  "gopls": {
+    "build.buildFlags": [
+      "-tags",
+      "synctrace"
+    ]
+  },
   "git.ignoreLimitWarning": true
 }

Makefile

@@ -12,7 +12,13 @@ BUILDKIT_FLAVOR := arm-rockchip830-linux-uclibcgnueabihf
 BUILDKIT_PATH ?= /opt/jetkvm-native-buildkit
 SKIP_NATIVE_IF_EXISTS ?= 0
 SKIP_UI_BUILD ?= 0
+ENABLE_SYNC_TRACE ?= 0
+
 GO_BUILD_ARGS := -tags netgo,timetzdata,nomsgpack
+ifeq ($(ENABLE_SYNC_TRACE), 1)
+	GO_BUILD_ARGS := $(GO_BUILD_ARGS),synctrace
+endif
+
 GO_RELEASE_BUILD_ARGS := -trimpath $(GO_BUILD_ARGS)
 GO_LDFLAGS := \
   -s -w \

internal/network/types/type.go

@@ -45,6 +45,8 @@ type IPv6StaticConfig struct {
 
 // NetworkConfig represents the complete network configuration for an interface
 type NetworkConfig struct {
+	DHCPClient null.String `json:"dhcp_client,omitempty" one_of:"jetdhcpc,udhcpc" default:"jetdhcpc"`
+
 	Hostname  null.String `json:"hostname,omitempty" validate_type:"hostname"`
 	HTTPProxy null.String `json:"http_proxy,omitempty" validate_type:"proxy"`
 	Domain    null.String `json:"domain,omitempty" validate_type:"hostname"`
@@ -145,6 +147,7 @@ type DHCPLease struct {
 	LeaseExpiry       *time.Time    `json:"lease_expiry,omitempty"`                    // The expiry time of the lease
 
 	InterfaceName string `json:"interface_name,omitempty"` // The name of the interface
+	DHCPClient    string `json:"dhcp_client,omitempty"`    // The DHCP client that obtained the lease
 }
 
 // InterfaceState represents the current state of a network interface
@@ -173,6 +176,31 @@ type NetworkConfigInterface interface {
 	IPv6Addresses() []IPAddress
 }
 
+// IsIPv6 returns true if the DHCP lease is for an IPv6 address
 func (d *DHCPLease) IsIPv6() bool {
 	return d.IPAddress.To4() == nil
 }
+
+// IPMask returns the IP mask for the DHCP lease
+func (d *DHCPLease) IPMask() net.IPMask {
+	if d.IsIPv6() {
+		// TODO: not implemented
+		return nil
+	}
+
+	mask := net.ParseIP(d.Netmask.String())
+	return net.IPv4Mask(mask[12], mask[13], mask[14], mask[15])
+}
+
+// IPNet returns the IP net for the DHCP lease
+func (d *DHCPLease) IPNet() *net.IPNet {
+	if d.IsIPv6() {
+		// TODO: not implemented
+		return nil
+	}
+
+	return &net.IPNet{
+		IP:   d.IPAddress,
+		Mask: d.IPMask(),
+	}
+}

internal/sync/log.go

@@ -0,0 +1,149 @@
+//go:build synctrace
+
+package sync
+
+import (
+	"fmt"
+	"reflect"
+	"runtime"
+	"sync"
+	"time"
+
+	"github.com/jetkvm/kvm/internal/logging"
+	"github.com/rs/zerolog"
+)
+
+var defaultLogger = logging.GetSubsystemLogger("synctrace")
+
+func logTrace(msg string) {
+	if defaultLogger.GetLevel() > zerolog.TraceLevel {
+		return
+	}
+
+	logTrack(3).Trace().Msg(msg)
+}
+
+func logTrack(callerSkip int) *zerolog.Logger {
+	l := *defaultLogger
+	if l.GetLevel() > zerolog.TraceLevel {
+		return &l
+	}
+
+	pc, file, no, ok := runtime.Caller(callerSkip)
+	if ok {
+		l = l.With().
+			Str("file", file).
+			Int("line", no).
+			Logger()
+
+		details := runtime.FuncForPC(pc)
+		if details != nil {
+			l = l.With().
+				Str("func", details.Name()).
+				Logger()
+		}
+	}
+
+	return &l
+}
+
+func logLockTrack(i string) *zerolog.Logger {
+	l := logTrack(4).
+		With().
+		Str("index", i).
+		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)
+}
+
+func increaseLockCount(i string) {
+	indexMu.Lock()
+	defer indexMu.Unlock()
+
+	if _, ok := lockCount[i]; !ok {
+		lockCount[i] = 0
+	}
+	lockCount[i]++
+
+	if _, ok := lastLock[i]; !ok {
+		lastLock[i] = time.Now()
+	}
+}
+
+func increaseUnlockCount(i string) {
+	indexMu.Lock()
+	defer indexMu.Unlock()
+
+	if _, ok := unlockCount[i]; !ok {
+		unlockCount[i] = 0
+	}
+	unlockCount[i]++
+}
+
+func logLock(t trackable) {
+	i := getIndex(t)
+	increaseLockCount(i)
+	logLockTrack(i).Trace().Msg("locking mutex")
+}
+
+func logUnlock(t trackable) {
+	i := getIndex(t)
+	increaseUnlockCount(i)
+	logLockTrack(i).Trace().Msg("unlocking mutex")
+}
+
+func logTryLock(t trackable) {
+	i := getIndex(t)
+	logLockTrack(i).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")
+}
+
+func logRLock(t trackable) {
+	i := getIndex(t)
+	increaseLockCount(i)
+	logLockTrack(i).Trace().Msg("locking mutex for reading")
+}
+
+func logRUnlock(t trackable) {
+	i := getIndex(t)
+	increaseUnlockCount(i)
+	logLockTrack(i).Trace().Msg("unlocking mutex for reading")
+}
+
+func logTryRLock(t trackable) {
+	i := getIndex(t)
+	logLockTrack(i).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")
+}

internal/sync/mutex.go

@@ -0,0 +1,69 @@
+//go:build synctrace
+
+package sync
+
+import (
+	gosync "sync"
+)
+
+// Mutex is a wrapper around the sync.Mutex
+type Mutex struct {
+	mu gosync.Mutex
+}
+
+// Lock locks the mutex
+func (m *Mutex) Lock() {
+	logLock(m)
+	m.mu.Lock()
+}
+
+// Unlock unlocks the mutex
+func (m *Mutex) Unlock() {
+	logUnlock(m)
+	m.mu.Unlock()
+}
+
+// TryLock tries to lock the mutex
+func (m *Mutex) TryLock() bool {
+	logTryLock(m)
+	l := m.mu.TryLock()
+	logTryLockResult(m, l)
+	return l
+}
+
+// RWMutex is a wrapper around the sync.RWMutex
+type RWMutex struct {
+	mu gosync.RWMutex
+}
+
+// Lock locks the mutex
+func (m *RWMutex) Lock() {
+	logLock(m)
+	m.mu.Lock()
+}
+
+// Unlock unlocks the mutex
+func (m *RWMutex) Unlock() {
+	logUnlock(m)
+	m.mu.Unlock()
+}
+
+// RLock locks the mutex for reading
+func (m *RWMutex) RLock() {
+	logRLock(m)
+	m.mu.RLock()
+}
+
+// RUnlock unlocks the mutex for reading
+func (m *RWMutex) RUnlock() {
+	logRUnlock(m)
+	m.mu.RUnlock()
+}
+
+// TryRLock tries to lock the mutex for reading
+func (m *RWMutex) TryRLock() bool {
+	logTryRLock(m)
+	l := m.mu.TryRLock()
+	logTryRLockResult(m, l)
+	return l
+}

internal/sync/once.go

@@ -0,0 +1,18 @@
+//go:build synctrace
+
+package sync
+
+import (
+	gosync "sync"
+)
+
+// Once is a wrapper around the sync.Once
+type Once struct {
+	mu gosync.Once
+}
+
+// Do calls the function f if and only if Do has not been called before for this instance of Once.
+func (o *Once) Do(f func()) {
+	logTrace("Doing once")
+	o.mu.Do(f)
+}

internal/sync/release.go

@@ -0,0 +1,92 @@
+//go:build !synctrace
+
+package sync
+
+import (
+	gosync "sync"
+)
+
+// Mutex is a wrapper around the sync.Mutex
+type Mutex struct {
+	mu gosync.Mutex
+}
+
+// Lock locks the mutex
+func (m *Mutex) Lock() {
+	m.mu.Lock()
+}
+
+// Unlock unlocks the mutex
+func (m *Mutex) Unlock() {
+	m.mu.Unlock()
+}
+
+// TryLock tries to lock the mutex
+func (m *Mutex) TryLock() bool {
+	return m.mu.TryLock()
+}
+
+// RWMutex is a wrapper around the sync.RWMutex
+type RWMutex struct {
+	mu gosync.RWMutex
+}
+
+// Lock locks the mutex
+func (m *RWMutex) Lock() {
+	m.mu.Lock()
+}
+
+// Unlock unlocks the mutex
+func (m *RWMutex) Unlock() {
+	m.mu.Unlock()
+}
+
+// RLock locks the mutex for reading
+func (m *RWMutex) RLock() {
+	m.mu.RLock()
+}
+
+// RUnlock unlocks the mutex for reading
+func (m *RWMutex) RUnlock() {
+	m.mu.RUnlock()
+}
+
+// TryRLock tries to lock the mutex for reading
+func (m *RWMutex) TryRLock() bool {
+	return m.mu.TryRLock()
+}
+
+// TryLock tries to lock the mutex
+func (m *RWMutex) TryLock() bool {
+	return m.mu.TryLock()
+}
+
+// WaitGroup is a wrapper around the sync.WaitGroup
+type WaitGroup struct {
+	wg gosync.WaitGroup
+}
+
+// Add adds a function to the wait group
+func (w *WaitGroup) Add(delta int) {
+	w.wg.Add(delta)
+}
+
+// Done decrements the wait group counter
+func (w *WaitGroup) Done() {
+	w.wg.Done()
+}
+
+// Wait waits for the wait group to finish
+func (w *WaitGroup) Wait() {
+	w.wg.Wait()
+}
+
+// Once is a wrapper around the sync.Once
+type Once struct {
+	mu gosync.Once
+}
+
+// Do calls the function f if and only if Do has not been called before for this instance of Once.
+func (o *Once) Do(f func()) {
+	o.mu.Do(f)
+}

internal/sync/waitgroup.go

@@ -0,0 +1,30 @@
+//go:build synctrace
+
+package sync
+
+import (
+	gosync "sync"
+)
+
+// WaitGroup is a wrapper around the sync.WaitGroup
+type WaitGroup struct {
+	wg gosync.WaitGroup
+}
+
+// Add adds a function to the wait group
+func (w *WaitGroup) Add(delta int) {
+	logTrace("Adding to wait group")
+	w.wg.Add(delta)
+}
+
+// Done decrements the wait group counter
+func (w *WaitGroup) Done() {
+	logTrace("Done with wait group")
+	w.wg.Done()
+}
+
+// Wait waits for the wait group to finish
+func (w *WaitGroup) Wait() {
+	logTrace("Waiting for wait group")
+	w.wg.Wait()
+}

internal/timesync/ntp.go

@@ -62,6 +62,7 @@ func (t *TimeSync) filterNTPServers(ntpServers []string) ([]string, error) {
 		if ip == nil {
 			continue
 		}
+
 		if hasIPv4 && ip.To4() != nil {
 			filteredServers = append(filteredServers, server)
 		}

internal/timesync/timesync.go

@@ -169,6 +169,9 @@ func (t *TimeSync) doTimeSync() {
 }
 
 func (t *TimeSync) Sync() error {
+	t.syncLock.Lock()
+	defer t.syncLock.Unlock()
+
 	var (
 		now    *time.Time
 		offset *time.Duration

pkg/nmlite/dhcp.go

@@ -18,21 +18,19 @@ type DHCPClient struct {
 	ifaceName  string
 	logger     *zerolog.Logger
 	client     types.DHCPClient
+	clientType string
 	link       netlink.Link
 
 	// Configuration
 	ipv4Enabled bool
 	ipv6Enabled bool
 
-	// State management
-	// stateManager *DHCPStateManager
-
 	// Callbacks
 	onLeaseChange func(lease *types.DHCPLease)
 }
 
 // NewDHCPClient creates a new DHCP client
-func NewDHCPClient(ctx context.Context, ifaceName string, logger *zerolog.Logger) (*DHCPClient, error) {
+func NewDHCPClient(ctx context.Context, ifaceName string, logger *zerolog.Logger, clientType string) (*DHCPClient, error) {
 	if ifaceName == "" {
 		return nil, fmt.Errorf("interface name cannot be empty")
 	}
@@ -45,6 +43,7 @@ func NewDHCPClient(ctx context.Context, ifaceName string, logger *zerolog.Logger
 		ctx:        ctx,
 		ifaceName:  ifaceName,
 		logger:     logger,
+		clientType: clientType,
 	}, nil
 }
 
@@ -70,10 +69,13 @@ func (dc *DHCPClient) SetOnLeaseChange(callback func(lease *types.DHCPLease)) {
 }
 
 func (dc *DHCPClient) initClient() (types.DHCPClient, error) {
-	if false {
+	switch dc.clientType {
+	case "jetdhcpc":
 		return dc.initJetDHCPC()
-	} else {
+	case "udhcpc":
 		return dc.initUDHCPC()
+	default:
+		return nil, fmt.Errorf("invalid client type: %s", dc.clientType)
 	}
 }
 
@@ -204,8 +206,11 @@ func (dc *DHCPClient) handleLeaseChange(lease *types.DHCPLease, isIPv6 bool) {
 		Str("ip", lease.IPAddress.String()).
 		Msg("DHCP lease changed")
 
+	// copy the lease to avoid race conditions
+	leaseCopy := *lease
+
 	// Notify callback
 	if dc.onLeaseChange != nil {
-		dc.onLeaseChange(lease)
+		dc.onLeaseChange(&leaseCopy)
 	}
 }

pkg/nmlite/hostname.go

@@ -6,7 +6,8 @@ import (
 	"os"
 	"os/exec"
 	"strings"
-	"sync"
+
+	"github.com/jetkvm/kvm/internal/sync"
 
 	"github.com/rs/zerolog"
 	"golang.org/x/net/idna"

pkg/nmlite/interface.go

@@ -4,9 +4,11 @@ import (
 	"context"
 	"fmt"
 	"net"
-	"sync"
+
 	"time"
 
+	"github.com/jetkvm/kvm/internal/sync"
+
 	"github.com/jetkvm/kvm/internal/confparser"
 	"github.com/jetkvm/kvm/internal/logging"
 	"github.com/jetkvm/kvm/internal/network/types"
@@ -78,7 +80,7 @@ func NewInterfaceManager(ctx context.Context, ifaceName string, config *types.Ne
 	}
 
 	// create the dhcp client
-	im.dhcpClient, err = NewDHCPClient(ctx, ifaceName, &scopedLogger)
+	im.dhcpClient, err = NewDHCPClient(ctx, ifaceName, &scopedLogger, config.DHCPClient.String)
 	if err != nil {
 		return nil, fmt.Errorf("failed to create DHCP client: %w", err)
 	}
@@ -562,7 +564,6 @@ func (im *InterfaceManager) monitorInterfaceState() {
 	defer im.wg.Done()
 
 	im.logger.Debug().Msg("monitoring interface state")
-
 	// TODO: use netlink subscription instead of polling
 	ticker := time.NewTicker(5 * time.Second)
 	defer ticker.Stop()
@@ -574,7 +575,6 @@ func (im *InterfaceManager) monitorInterfaceState() {
 		case <-im.stopCh:
 			return
 		case <-ticker.C:
-			im.logger.Debug().Msg("checking interface state")
 			if err := im.updateInterfaceState(); err != nil {
 				im.logger.Error().Err(err).Msg("failed to update interface state")
 			}
@@ -727,12 +727,9 @@ func (im *InterfaceManager) applyDHCPLease(lease *types.DHCPLease) error {
 
 // convertDHCPLeaseToIPv4Config converts a DHCP lease to IPv4Config
 func (im *InterfaceManager) convertDHCPLeaseToIPv4Config(lease *types.DHCPLease) *types.IPAddress {
-	mask := lease.Netmask
-
-	// Create IPNet from IP and netmask
-	ipNet := &net.IPNet{
-		IP:   lease.IPAddress,
-		Mask: net.IPv4Mask(mask[12], mask[13], mask[14], mask[15]),
+	ipNet := lease.IPNet()
+	if ipNet == nil {
+		return nil
 	}
 
 	// Create IPv4Address

pkg/nmlite/jetdhcpc/client.go

@@ -6,9 +6,11 @@ import (
 	"fmt"
 	"net"
 	"slices"
-	"sync"
+
 	"time"
 
+	"github.com/jetkvm/kvm/internal/sync"
+
 	"github.com/go-co-op/gocron/v2"
 	"github.com/insomniacslk/dhcp/dhcpv4"
 	"github.com/insomniacslk/dhcp/dhcpv6"

pkg/nmlite/jetdhcpc/lease.go

@@ -33,7 +33,9 @@ type Lease struct {
 
 // ToDHCPLease converts a lease to a DHCP lease.
 func (l *Lease) ToDHCPLease() *types.DHCPLease {
-	return &l.DHCPLease
+	lease := &l.DHCPLease
+	lease.DHCPClient = "jetdhcpc"
+	return lease
 }
 
 // fromNclient4Lease creates a lease from a nclient4.Lease.
@@ -45,9 +47,9 @@ func fromNclient4Lease(l *nclient4.Lease, iface string) *Lease {
 	// only the fields that we need are set
 	lease.Routers = l.ACK.Router()
 	lease.IPAddress = l.ACK.YourIPAddr
+
 	lease.Netmask = net.IP(l.ACK.SubnetMask())
 	lease.Broadcast = l.ACK.BroadcastAddress()
-	// lease.MTU = int(resp.Options.Get(dhcpv4.OptionInterfaceMTU))
 
 	lease.NTPServers = l.ACK.NTPServers()
 

pkg/nmlite/link/netlink.go

@@ -10,9 +10,10 @@ import (
 	"path"
 	"strconv"
 	"strings"
-	"sync"
 	"time"
 
+	"github.com/jetkvm/kvm/internal/sync"
+
 	"github.com/jetkvm/kvm/internal/network/types"
 	"github.com/rs/zerolog"
 	"github.com/vishvananda/netlink"

pkg/nmlite/manager.go

@@ -6,7 +6,8 @@ package nmlite
 import (
 	"context"
 	"fmt"
-	"sync"
+
+	"github.com/jetkvm/kvm/internal/sync"
 
 	"github.com/jetkvm/kvm/internal/logging"
 	"github.com/jetkvm/kvm/internal/network/types"

pkg/nmlite/udhcpc/parser.go

@@ -40,7 +40,9 @@ func (l *Lease) ToJSON() string {
 
 // ToDHCPLease converts a lease to a DHCP lease.
 func (l *Lease) ToDHCPLease() *types.DHCPLease {
-	return &l.DHCPLease
+	lease := &l.DHCPLease
+	lease.DHCPClient = "udhcpc"
+	return lease
 }
 
 // SetLeaseExpiry sets the lease expiry time.

pkg/nmlite/udhcpc/udhcpc.go

@@ -6,9 +6,11 @@ import (
 	"os"
 	"path/filepath"
 	"reflect"
-	"sync"
+
 	"time"
 
+	"github.com/jetkvm/kvm/internal/sync"
+
 	"github.com/fsnotify/fsnotify"
 	"github.com/jetkvm/kvm/internal/network/types"
 	"github.com/rs/zerolog"

scripts/dev_deploy.sh

@@ -17,6 +17,7 @@ show_help() {
     echo "      --skip-ui-build        Skip frontend/UI build"
     echo "      --skip-native-build    Skip native build"
     echo "      --disable-docker       Disable docker build"
+    echo "      --enable-sync-trace    Enable sync trace (do not use in release builds)"
     echo "  -i, --install              Build for release and install the app"
     echo "      --help                 Display this help message"
     echo
@@ -32,6 +33,7 @@ REMOTE_PATH="/userdata/jetkvm/bin"
 SKIP_UI_BUILD=false
 SKIP_UI_BUILD_RELEASE=0
 SKIP_NATIVE_BUILD=0
+ENABLE_SYNC_TRACE=0
 RESET_USB_HID_DEVICE=false
 LOG_TRACE_SCOPES="${LOG_TRACE_SCOPES:-jetkvm,cloud,websocket,native,jsonrpc}"
 RUN_GO_TESTS=false
@@ -64,6 +66,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
@@ -180,7 +187,10 @@ fi
 if [ "$INSTALL_APP" = true ]
 then
 	msg_info "▶ Building release binary"
-	do_make build_release SKIP_NATIVE_IF_EXISTS=${SKIP_NATIVE_BUILD} SKIP_UI_BUILD=${SKIP_UI_BUILD_RELEASE}
+	do_make build_release \
+    SKIP_NATIVE_IF_EXISTS=${SKIP_NATIVE_BUILD} \
+    SKIP_UI_BUILD=${SKIP_UI_BUILD_RELEASE} \
+    ENABLE_SYNC_TRACE=${ENABLE_SYNC_TRACE}
 	
 	# Copy the binary to the remote host as if we were the OTA updater.
 	ssh "${REMOTE_USER}@${REMOTE_HOST}" "cat > /userdata/jetkvm/jetkvm_app.update" < bin/jetkvm_app
@@ -189,7 +199,10 @@ then
 	ssh "${REMOTE_USER}@${REMOTE_HOST}" "reboot"
 else
 	msg_info "▶ Building development binary"
-	do_make build_dev SKIP_NATIVE_IF_EXISTS=${SKIP_NATIVE_BUILD} SKIP_UI_BUILD=${SKIP_UI_BUILD_RELEASE}
+	do_make build_dev \
+    SKIP_NATIVE_IF_EXISTS=${SKIP_NATIVE_BUILD} \
+    SKIP_UI_BUILD=${SKIP_UI_BUILD_RELEASE} \
+    ENABLE_SYNC_TRACE=${ENABLE_SYNC_TRACE}
 	
 	# Kill any existing instances of the application
 	ssh "${REMOTE_USER}@${REMOTE_HOST}" "killall jetkvm_app_debug || true"

ui/src/components/DhcpLeaseCard.tsx

@@ -221,6 +221,13 @@ export default function DhcpLeaseCard({
                   </span>
                 </div>
               )}
+
+              {networkState?.dhcp_lease?.dhcp_client && (
+                <div className="flex justify-between border-t border-slate-800/10 pt-2 dark:border-slate-300/20">
+                  <span className="text-sm text-slate-600 dark:text-slate-400">DHCP Client</span>
+                  <span className="text-sm font-medium">{networkState?.dhcp_lease?.dhcp_client}</span>
+                </div>
+              )}
             </div>
           </div>
         </div>

ui/src/hooks/stores.ts

@@ -690,6 +690,7 @@ export interface DhcpLease {
   message?: string;
   tftp?: string;
   bootfile?: string;
+  dhcp_client?: string;
 }
 
 export interface IPv6Address {