lib/sync, lib/model: Capture locker routine ID, print locker details on deadlock

lib/model/model.go

@@ -173,8 +173,8 @@ func NewModel(cfg *config.Wrapper, id protocol.DeviceID, deviceName, clientName,
 // period.
 func (m *Model) StartDeadlockDetector(timeout time.Duration) {
 	l.Infof("Starting deadlock detector with %v timeout", timeout)
-	deadlockDetect(m.fmut, timeout)
+	deadlockDetect(m.fmut, timeout, "fmut")
-	deadlockDetect(m.pmut, timeout)
+	deadlockDetect(m.pmut, timeout, "pmut")
 }
 
 // StartFolder constructs the folder service and starts it.

lib/model/util.go

@@ -7,11 +7,16 @@
 package model
 
 import (
+	"fmt"
 	"sync"
 	"time"
 )
 
-func deadlockDetect(mut sync.Locker, timeout time.Duration) {
+type Holder interface {
+	Holder() (string, int)
+}
+
+func deadlockDetect(mut sync.Locker, timeout time.Duration, name string) {
 	go func() {
 		for {
 			time.Sleep(timeout / 4)
@@ -29,7 +34,12 @@ func deadlockDetect(mut sync.Locker, timeout time.Duration) {
 			}()
 
 			if r := <-ok; !r {
-				panic("deadlock detected")
+				msg := fmt.Sprintf("deadlock detected at %s", name)
+				if hmut, ok := mut.(Holder); ok {
+					holder, goid := hmut.Holder()
+					msg = fmt.Sprintf("deadlock detected at %s, current holder: %s at routine %d", name, holder, goid)
+				}
+				panic(msg)
 			}
 		}
 	}()

lib/sync/sync.go

@@ -10,6 +10,7 @@ import (
 	"fmt"
 	"path/filepath"
 	"runtime"
+	"strconv"
 	"strings"
 	"sync"
 	"sync/atomic"
@@ -60,12 +61,14 @@ type loggedMutex struct {
 	sync.Mutex
 	start    time.Time
 	lockedAt string
+	goid     int
 }
 
 func (m *loggedMutex) Lock() {
 	m.Mutex.Lock()
 	m.start = time.Now()
 	m.lockedAt = getCaller()
+	m.goid = goid()
 }
 
 func (m *loggedMutex) Unlock() {
@@ -76,10 +79,15 @@ func (m *loggedMutex) Unlock() {
 	m.Mutex.Unlock()
 }
 
+func (m *loggedMutex) Holder() (string, int) {
+	return m.lockedAt, m.goid
+}
+
 type loggedRWMutex struct {
 	sync.RWMutex
 	start    time.Time
 	lockedAt string
+	goid     int
 
 	logUnlockers uint32
 
@@ -98,6 +106,7 @@ func (m *loggedRWMutex) Lock() {
 	duration := m.start.Sub(start)
 
 	m.lockedAt = getCaller()
+	m.goid = goid()
 	if duration > threshold {
 		l.Debugf("RWMutex took %v to lock. Locked at %s. RUnlockers while locking: %s", duration, m.lockedAt, strings.Join(m.unlockers, ", "))
 	}
@@ -139,3 +148,14 @@ func getCaller() string {
 	file = filepath.Join(filepath.Base(filepath.Dir(file)), filepath.Base(file))
 	return fmt.Sprintf("%s:%d", file, line)
 }
+
+func goid() int {
+	var buf [64]byte
+	n := runtime.Stack(buf[:], false)
+	idField := strings.Fields(strings.TrimPrefix(string(buf[:n]), "goroutine "))[0]
+	id, err := strconv.Atoi(idField)
+	if err != nil {
+		return -1
+	}
+	return id
+}