diff --git a/DEVELOPMENT.md b/DEVELOPMENT.md index 0ab65c4f..687a6266 100644 --- a/DEVELOPMENT.md +++ b/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 ``` @@ -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) @@ -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 --enable-sync-trace +``` + --- ## Next Steps diff --git a/cloud.go b/cloud.go index dbbd3bbc..3474b9a6 100644 --- a/cloud.go +++ b/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" ) diff --git a/config.go b/config.go index 5a3e7dc8..fdb4508c 100644 --- a/config.go +++ b/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" ) diff --git a/display.go b/display.go index 68723b59..bfb6751f 100644 --- a/display.go +++ b/display.go @@ -7,9 +7,10 @@ import ( "os" "strconv" "strings" - "sync" "time" + "github.com/jetkvm/kvm/internal/sync" + "github.com/prometheus/common/version" ) diff --git a/failsafe.go b/failsafe.go index 3c6b3d3a..ee56a494 100644 --- a/failsafe.go +++ b/failsafe.go @@ -4,7 +4,8 @@ import ( "fmt" "os" "strings" - "sync" + + "github.com/jetkvm/kvm/internal/sync" ) const ( diff --git a/hw.go b/hw.go index 7797adc1..37a19b5c 100644 --- a/hw.go +++ b/hw.go @@ -6,8 +6,9 @@ import ( "os/exec" "regexp" "strings" - "sync" "time" + + "github.com/jetkvm/kvm/internal/sync" ) func extractSerialNumber() (string, error) { diff --git a/internal/mdns/mdns.go b/internal/mdns/mdns.go index 2b954d45..bf2949e4 100644 --- a/internal/mdns/mdns.go +++ b/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" diff --git a/internal/native/native.go b/internal/native/native.go index cb8761cf..792ee747 100644 --- a/internal/native/native.go +++ b/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" ) diff --git a/internal/native/single.go b/internal/native/single.go index 0782b28c..240a348e 100644 --- a/internal/native/single.go +++ b/internal/native/single.go @@ -1,6 +1,6 @@ package native -import "sync" +import "github.com/jetkvm/kvm/internal/sync" var ( instance *Native diff --git a/internal/sync/log.go b/internal/sync/log.go index 36d0b29c..a7894423 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 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) + } } 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/internal/timesync/timesync.go b/internal/timesync/timesync.go index 97cee97d..088f5359 100644 --- a/internal/timesync/timesync.go +++ b/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" ) diff --git a/internal/usbgadget/hid_keyboard.go b/internal/usbgadget/hid_keyboard.go index 74cf76f9..f50baf5b 100644 --- a/internal/usbgadget/hid_keyboard.go +++ b/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" ) diff --git a/internal/usbgadget/usbgadget.go b/internal/usbgadget/usbgadget.go index f01ae09d..e9d352c0 100644 --- a/internal/usbgadget/usbgadget.go +++ b/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" ) diff --git a/internal/usbgadget/utils.go b/internal/usbgadget/utils.go index 85bf1579..7ec32a23 100644 --- a/internal/usbgadget/utils.go +++ b/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" ) diff --git a/internal/websecure/store.go b/internal/websecure/store.go index ea7911c4..aed051ca 100644 --- a/internal/websecure/store.go +++ b/internal/websecure/store.go @@ -6,7 +6,8 @@ import ( "os" "path" "strings" - "sync" + + "github.com/jetkvm/kvm/internal/sync" "github.com/rs/zerolog" ) 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 { diff --git a/native.go b/native.go index 81a0e50d..d2390265 100644 --- a/native.go +++ b/native.go @@ -2,11 +2,12 @@ package kvm import ( "os" - "sync" "time" - "github.com/Masterminds/semver/v3" "github.com/jetkvm/kvm/internal/native" + "github.com/jetkvm/kvm/internal/sync" + + "github.com/Masterminds/semver/v3" "github.com/pion/webrtc/v4/pkg/media" ) diff --git a/usb_mass_storage.go b/usb_mass_storage.go index 0f1f4b93..5f444deb 100644 --- a/usb_mass_storage.go +++ b/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 { diff --git a/web_tls.go b/web_tls.go index 41f532ea..913302d9 100644 --- a/web_tls.go +++ b/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" ) diff --git a/webrtc.go b/webrtc.go index 46fca2b8..6b7d1391 100644 --- a/webrtc.go +++ b/webrtc.go @@ -6,15 +6,16 @@ import ( "encoding/json" "net" "strings" - "sync" "time" + "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/hidrpc" - "github.com/jetkvm/kvm/internal/logging" - "github.com/jetkvm/kvm/internal/usbgadget" "github.com/pion/webrtc/v4" "github.com/rs/zerolog" )