Compare commits

..

2 Commits

Author SHA1 Message Date
Siyuan aef26459d3 use sync trace to track mutexes to make deadlock analysis easier 2025-10-07 23:12:20 +00:00
Siyuan b04b148a4b feat: add sync trace 2025-10-07 23:11:53 +00:00
22 changed files with 471 additions and 35 deletions

View File

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

View File

@ -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 \

View File

@ -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(),
}
}

149
internal/sync/log.go Normal file
View File

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

69
internal/sync/mutex.go Normal file
View File

@ -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
}

18
internal/sync/once.go Normal file
View File

@ -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)
}

92
internal/sync/release.go Normal file
View File

@ -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)
}

View File

@ -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()
}

View File

@ -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)
}

View File

@ -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

View File

@ -14,25 +14,23 @@ import (
// DHCPClient wraps the dhclient package for use in the network manager
type DHCPClient struct {
ctx context.Context
ifaceName string
logger *zerolog.Logger
client types.DHCPClient
link netlink.Link
ctx context.Context
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")
}
@ -42,9 +40,10 @@ func NewDHCPClient(ctx context.Context, ifaceName string, logger *zerolog.Logger
}
return &DHCPClient{
ctx: ctx,
ifaceName: ifaceName,
logger: 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)
}
}

View File

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

View File

@ -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

View File

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

View File

@ -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()

View File

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

View File

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

View File

@ -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.

View File

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

View File

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

View File

@ -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>

View File

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