tailscale/syncs/mutex_debug.go

// Copyright (c) Tailscale Inc & AUTHORS
// SPDX-License-Identifier: BSD-3-Clause

//go:build ts_mutex_debug

package syncs

import (
	"bytes"
	"fmt"
	"log"
	"runtime"
	"sync"
	"unsafe"

	"go4.org/mem"
)

// MutexDebugging indicates whether the "ts_mutex_debug" build tag is set
// and mutex debugging is enabled.
const MutexDebugging = true

type Mutex struct {
	sync.Mutex
}

type RWMutex struct {
	sync.RWMutex
}

func RequiresMutex(mu *Mutex) {
	// TODO: check
}

// TODO(bradfitz): actually track stuff when in debug mode.

var bufPool = &sync.Pool{
	New: func() any {
		b := make([]byte, 16<<10)
		return &b
	},
}

func (m *Mutex) Lock() {
	defer m.Mutex.Lock()

	gid := curGoroutineID()

	up := uintptr((unsafe.Pointer)(m))

	bufp := bufPool.Get().(*[]byte)
	defer bufPool.Put(bufp)
	stack := (*bufp)[:runtime.Stack(*bufp, false)]

	trackMu.Lock()
	defer trackMu.Unlock()
	gid = walkToParent(gid)

	name, ok := mutexName[up]
	if !ok {
		name = "unnamed"
		log.Printf("XXX unregistered Mutex.Lock %p called from:\n%s", m, stack)
	}

	switch name {
	case "ipnlocal.LocalBackend.mu", "wgengine.userspaceEngine.wgLock", "ipnlocal.nodeBackend.mu":
		if bytes.Contains(stack, []byte("wireguard-go/device.(*Device).RoutineReceiveIncoming")) {
			log.Printf("XXX mutex Lock from wireguard land: %s, %s", name, stack)
		}
	}

	gi, ok := goroutines[gid]
	if !ok {
		gi = &goroutineInfo{}
		goroutines[gid] = gi
	}
	gi.holding = append(gi.holding, &heldLock{
		mutexAddr: up,
		name:      name,
	})
	if len(gi.holding) > 1 {
		names := make([]string, 0, len(gi.holding))
		for i, hl := range gi.holding {
			names = append(names, hl.name)

			if i == 0 {
				continue
			}
			lo := lockOrder{
				first:  gi.holding[i-1].name,
				second: hl.name,
			}
			if lockOrders[lo.reverse()] {
				log.Printf("mutex: potential deadlock detected: lock order violation: %q then %q (saw reverse order before); goroutine %d stack:\n%s", lo.first, lo.second, gid, stack)
			} else {
				if _, ok := lockOrders[lo]; !ok {
					log.Printf("XXX learned new lock order: %q then %q", lo.first, lo.second)
					lockOrders[lo] = true
				}
			}
		}
		log.Printf("XXX goroutine %v holding %q", gid, names)
	}
}

func (m *Mutex) Unlock() {
	defer m.Mutex.Unlock()
	up := uintptr((unsafe.Pointer)(m))

	gid := curGoroutineID()
	trackMu.Lock()
	defer trackMu.Unlock()
	gid = walkToParent(gid)

	name, ok := mutexName[up]
	if !ok {
		name = "unnamed"
	}

	gi, ok := goroutines[gid]
	if !ok || len(gi.holding) == 0 {
		log.Printf("mutex: unlock of %p (%s) by goroutine %d with no held locks", m, name, gid)
		return
	}
	last := gi.holding[len(gi.holding)-1]
	if last.mutexAddr != up {
		log.Printf("mutex: unlock of %p (%s) by goroutine %d, but last held lock is %p (%s)", m, name, gid, last.mutexAddr, last.name)
		return
	}
	gi.holding[len(gi.holding)-1] = nil
	gi.holding = gi.holding[:len(gi.holding)-1]
	if len(gi.holding) == 0 {
		delete(goroutines, gid)
	}
}

var (
	trackMu    sync.Mutex
	mutexName  = make(map[uintptr]string)
	goroutines = make(map[uint64]*goroutineInfo)
	parentGID  = make(map[uint64]uint64)  // child goroutine ID -> parent (for ForkJoinGo)
	lockOrders = make(map[lockOrder]bool) // observed lock orderings
)

type lockOrder struct {
	first  string
	second string
}

func (lo lockOrder) reverse() lockOrder {
	return lockOrder{first: lo.second, second: lo.first}
}

type goroutineInfo struct {
	holding []*heldLock
}

type heldLock struct {
	mutexAddr uintptr
	name      string
	// TODO: stack? [16]uintptr?
}

// RegisterMutex registers the given mutex with the given name for
// debugging purposes.
func RegisterMutex(mu *Mutex, name string) {
	trackMu.Lock()
	defer trackMu.Unlock()
	up := uintptr((unsafe.Pointer)(mu))
	mutexName[up] = name
	runtime.AddCleanup(mu, func(up uintptr) {
		trackMu.Lock()
		defer trackMu.Unlock()
		delete(mutexName, up)
	}, up)
}

var littleBuf = sync.Pool{
	New: func() interface{} {
		buf := make([]byte, 64)
		return &buf
	},
}

var goroutineSpace = []byte("goroutine ")

func curGoroutineID() uint64 {
	bp := littleBuf.Get().(*[]byte)
	defer littleBuf.Put(bp)
	b := *bp
	b = b[:runtime.Stack(b, false)]
	// Parse the 4707 out of "goroutine 4707 ["
	b = bytes.TrimPrefix(b, goroutineSpace)
	i := bytes.IndexByte(b, ' ')
	if i < 0 {
		panic(fmt.Sprintf("No space found in %q", b))
	}
	b = b[:i]
	n, err := mem.ParseUint(mem.B(b), 10, 64)
	if err != nil {
		panic(fmt.Sprintf("Failed to parse goroutine ID out of %q: %v", b, err))
	}
	return n
}

func trackForkJoinPair(parent, child uint64, add bool) {
	trackMu.Lock()
	defer trackMu.Unlock()
	if add {
		parentGID[child] = parent
	} else {
		delete(parentGID, child)
	}
}

func walkToParent(gid uint64) uint64 {
	for {
		p, ok := parentGID[gid]
		if !ok {
			return gid
		}
		gid = p
	}
}

// ForkJoinGo is like go fn() but indicates that the goroutine
// is part of a fork-join parallelism pattern.
//
// This compiles to just "go fn()" in non-debug builds.
func ForkJoinGo(fn func()) {
	parentGID := curGoroutineID()
	go func() {
		childGID := curGoroutineID()
		trackForkJoinPair(parentGID, childGID, true)
		defer trackForkJoinPair(parentGID, childGID, false)
		fn()
	}()
}