Skip to content

Commit

Permalink
Add unit tests and an environment flag to enable the debugsync functi…
Browse files Browse the repository at this point in the history
…onality
  • Loading branch information
jbsv committed Sep 14, 2022
1 parent 6391c5c commit 68d6262
Show file tree
Hide file tree
Showing 11 changed files with 510 additions and 629 deletions.
3 changes: 2 additions & 1 deletion .github/workflows/go_test.yml
Original file line number Diff line number Diff line change
Expand Up @@ -12,7 +12,8 @@ jobs:
platform: [ubuntu-latest, macos-latest, windows-latest]
runs-on: ${{matrix.platform}}
env:
LLVL: trace
DBGSYNCLOG: trace
DBGSYNCON: true
steps:
- name: Set up Go ^1.19
uses: actions/setup-go@v2
Expand Down
16 changes: 1 addition & 15 deletions go.mod
Original file line number Diff line number Diff line change
Expand Up @@ -2,18 +2,4 @@ module github.com/dedis/debugsync

go 1.19

require (
github.com/rs/zerolog v1.19.0
github.com/stretchr/testify v1.8.0
)

require (
github.com/davecgh/go-spew v1.1.1 // indirect
github.com/kr/text v0.2.0 // indirect
github.com/niemeyer/pretty v0.0.0-20200227124842-a10e7caefd8e // indirect
github.com/pmezard/go-difflib v1.0.0 // indirect
go.dedis.ch/dela v0.0.0-20220909115533-ad4f281a552f // indirect
golang.org/x/tools v0.1.11-0.20220316014157-77aa08bb151a // indirect
gopkg.in/check.v1 v1.0.0-20200902074654-038fdea0a05b // indirect
gopkg.in/yaml.v3 v3.0.1 // indirect
)
require github.com/rs/zerolog v1.19.0
521 changes: 0 additions & 521 deletions go.sum

Large diffs are not rendered by default.

15 changes: 11 additions & 4 deletions mod.go
Original file line number Diff line number Diff line change
Expand Up @@ -4,8 +4,8 @@
// It is disabled by default and the level can be increased using
// an environment variable:
//
// LLVL=trace go test ./...
// LLVL=info go test ./...
// DBGSYNCLOG=trace go test ./...
// DBGSYNCLOG=info go test ./...
package debugsync

import (
Expand All @@ -17,11 +17,15 @@ import (

// EnvLogLevel is the name of the environment variable to change the logging
// level.
const EnvLogLevel = "LLVL"
const EnvLogLevel = "DBGSYNCLOG"
const DebugFlag = "DBGSYNCON"

const defaultLevel = zerolog.NoLevel

func init() {
dbg := os.Getenv(DebugFlag)
DebugIsOn = dbg == "true"

lvl := os.Getenv(EnvLogLevel)

var level zerolog.Level
Expand All @@ -40,7 +44,7 @@ func init() {
case "":
level = defaultLevel
default:
level = zerolog.TraceLevel
level = zerolog.Disabled
}

Logger = Logger.Level(level)
Expand All @@ -56,3 +60,6 @@ var logout = zerolog.ConsoleWriter{
var Logger = zerolog.New(logout).Level(defaultLevel).
With().Timestamp().Logger().
With().Caller().Logger()

// DebugIsOn allows to turn the debugging tool on
var DebugIsOn = false
21 changes: 14 additions & 7 deletions mutex.go
Original file line number Diff line number Diff line change
Expand Up @@ -25,12 +25,16 @@ type Mutex struct {
// If the lock is already in use, the calling goroutine
// blocks until the mutex is available.
func (m *Mutex) Lock() {
Logger.Debug().Msg("Locking")
locking := startLockTimer("RWMutex timed out when acquiring lock", debug.Stack())
m.mutex.Lock()
close(locking)
if DebugIsOn {
Logger.Debug().Msg("Locking")
locking := startLockTimer("RWMutex timed out when acquiring lock", debug.Stack())
m.mutex.Lock()
close(locking)

m.unlocking = startLockTimer("RWMutex timed out before releasing lock", debug.Stack())
m.unlocking = startLockTimer("RWMutex timed out before releasing lock", debug.Stack())
} else {
m.mutex.Lock()
}
}

// TryLock tries to lock m and reports whether it succeeded.
Expand All @@ -41,7 +45,7 @@ func (m *Mutex) Lock() {
func (m *Mutex) TryLock() bool {
locked := m.mutex.TryLock()

if locked {
if DebugIsOn && locked {
m.unlocking = startLockTimer("RWMutex timed out before releasing lock", debug.Stack())
}

Expand All @@ -55,6 +59,9 @@ func (m *Mutex) TryLock() bool {
// It is allowed for one goroutine to lock a Mutex and then
// arrange for another goroutine to unlock it.
func (m *Mutex) Unlock() {
close(m.unlocking)
if DebugIsOn && m.unlocking != nil {
close(m.unlocking)
m.unlocking = nil
}
m.mutex.Unlock()
}
187 changes: 187 additions & 0 deletions mutex_test.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,187 @@
// Copyright 2009 The Go Authors. All rights reserved.
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.

// GOMAXPROCS=10 go test

package debugsync

import (
"fmt"

"os"
"os/exec"
"runtime"
"strings"
"testing"
"time"
)

func HammerMutex(m *Mutex, loops int, cdone chan bool) {
for i := 0; i < loops; i++ {
if i%3 == 0 {
if m.TryLock() {
m.Unlock()
}
continue
}
m.Lock()
m.Unlock()
}
cdone <- true
}

func TestMutex(t *testing.T) {
if n := runtime.SetMutexProfileFraction(1); n != 0 {
t.Logf("got mutexrate %d expected 0", n)
}
defer runtime.SetMutexProfileFraction(0)

m := new(Mutex)

m.Lock()
if m.TryLock() {
t.Fatalf("TryLock succeeded with mutex locked")
}
m.Unlock()
if !m.TryLock() {
t.Fatalf("TryLock failed with mutex unlocked")
}
m.Unlock()

c := make(chan bool)
for i := 0; i < 10; i++ {
go HammerMutex(m, 1000, c)
}
for i := 0; i < 10; i++ {
<-c
}
}

var misuseTests = []struct {
name string
f func()
}{
{
"Mutex.Unlock",
func() {
var mu Mutex
mu.Unlock()
},
},
{
"Mutex.Unlock2",
func() {
var mu Mutex
mu.Lock()
mu.Unlock()
mu.Unlock()
},
},
{
"RWMutex.Unlock",
func() {
var mu RWMutex
mu.Unlock()
},
},
{
"RWMutex.Unlock2",
func() {
var mu RWMutex
mu.RLock()
mu.Unlock()
},
},
{
"RWMutex.Unlock3",
func() {
var mu RWMutex
mu.Lock()
mu.Unlock()
mu.Unlock()
},
},
{
"RWMutex.RUnlock",
func() {
var mu RWMutex
mu.RUnlock()
},
},
{
"RWMutex.RUnlock2",
func() {
var mu RWMutex
mu.Lock()
mu.RUnlock()
},
},
{
"RWMutex.RUnlock3",
func() {
var mu RWMutex
mu.RLock()
mu.RUnlock()
mu.RUnlock()
},
},
}

func init() {
if len(os.Args) == 3 && os.Args[1] == "TESTMISUSE" {
for _, test := range misuseTests {
if test.name == os.Args[2] {
func() {
defer func() { recover() }()
test.f()
}()
fmt.Printf("test completed\n")
os.Exit(0)
}
}
fmt.Printf("unknown test\n")
os.Exit(0)
}
}

func TestMutexMisuse(t *testing.T) {
for _, test := range misuseTests {
out, err := exec.Command(os.Args[0], "TESTMISUSE", test.name).CombinedOutput()
if err == nil || !strings.Contains(string(out), "unlocked") {
t.Errorf("%s: did not find failure with message about unlocked lock: %s\n%s\n", test.name, err, out)
}
}
}

func TestMutexFairness(t *testing.T) {
var mu Mutex
stop := make(chan bool)
defer close(stop)
go func() {
for {
mu.Lock()
time.Sleep(100 * time.Microsecond)
mu.Unlock()
select {
case <-stop:
return
default:
}
}
}()
done := make(chan bool, 1)
go func() {
for i := 0; i < 10; i++ {
time.Sleep(100 * time.Microsecond)
mu.Lock()
mu.Unlock()
}
done <- true
}()
select {
case <-done:
case <-time.After(10 * time.Second):
t.Fatalf("can't acquire Mutex in 10 seconds")
}
}
49 changes: 36 additions & 13 deletions rwmutex.go
Original file line number Diff line number Diff line change
Expand Up @@ -36,11 +36,15 @@ type RWMutex struct {
// If the lock is already locked for reading or writing,
// Lock blocks until the lock is available.
func (m *RWMutex) Lock() {
locking := startLockTimer("RWMutex timed out when acquiring lock", debug.Stack())
m.mutex.Lock()
close(locking)
if DebugIsOn {
locking := startLockTimer("RWMutex timed out when acquiring lock", debug.Stack())
m.mutex.Lock()
close(locking)

m.unlocking = startLockTimer("RWMutex timed out before releasing lock", debug.Stack())
m.unlocking = startLockTimer("RWMutex timed out before releasing lock", debug.Stack())
} else {
m.mutex.Lock()
}
}

// TryLock tries to lock rw for writing and reports whether it succeeded.
Expand All @@ -51,7 +55,7 @@ func (m *RWMutex) Lock() {
func (m *RWMutex) TryLock() bool {
locked := m.mutex.TryLock()

if locked {
if DebugIsOn && locked {
m.unlocking = startLockTimer("RWMutex timed out before releasing lock", debug.Stack())
}

Expand All @@ -65,7 +69,10 @@ func (m *RWMutex) TryLock() bool {
// goroutine. One goroutine may RLock (Lock) a RWMutex and then
// arrange for another goroutine to RUnlock (Unlock) it.
func (m *RWMutex) Unlock() {
close(m.unlocking)
if DebugIsOn && m.unlocking != nil {
close(m.unlocking)
m.unlocking = nil
}
m.mutex.Unlock()
}

Expand All @@ -88,11 +95,15 @@ func (m *RWMutex) Unlock() {
// call excludes new readers from acquiring the lock. See the
// documentation on the RWMutex type.
func (m *RWMutex) RLock() {
locking := startLockTimer("RWMutex timed out when acquiring RLock", debug.Stack())
m.mutex.RLock()
close(locking)
if DebugIsOn {
locking := startLockTimer("RWMutex timed out when acquiring RLock", debug.Stack())
m.mutex.RLock()
close(locking)

m.startRLockTimer("RMutex timed out before releasing RLock", debug.Stack())
m.startRLockTimer("RMutex timed out before releasing RLock", debug.Stack())
} else {
m.mutex.RLock()
}
}

// TryRLock tries to lock rw for reading and reports whether it succeeded.
Expand All @@ -102,7 +113,7 @@ func (m *RWMutex) RLock() {
// in a particular use of mutexes.
func (m *RWMutex) TryRLock() bool {
locked := m.mutex.TryRLock()
if locked {
if DebugIsOn && locked {
m.startRLockTimer("RMutex timed out before releasing RLock", debug.Stack())
}
return locked
Expand All @@ -113,8 +124,20 @@ func (m *RWMutex) TryRLock() bool {
// It is a run-time error if rw is not locked for reading
// on entry to RUnlock.
func (m *RWMutex) RUnlock() {
m.wg.Done()
m.mutex.RUnlock()
defer m.mutex.RUnlock()

if DebugIsOn {
m.wg.Done()
defer func() {
err := recover()
if err != nil {
// when m.wg goes bellow zero,
// we need to recover from panic for the unit tests,
// re-init the wg
m.wg = sync.WaitGroup{}
}
}()
}
}

func (m *RWMutex) startRLockTimer(msg string, stack []byte) {
Expand Down
Loading

0 comments on commit 68d6262

Please sign in to comment.