syncthing/lib/sync/sync_test.go

350 lines
6.8 KiB
Go
Raw Normal View History

// Copyright (C) 2015 The Syncthing Authors.
//
// This Source Code Form is subject to the terms of the Mozilla Public
// License, v. 2.0. If a copy of the MPL was not distributed with this file,
// You can obtain one at https://mozilla.org/MPL/2.0/.
package sync
import (
"strings"
"sync"
"testing"
"time"
Implement facility based logger, debugging via REST API This implements a new debug/trace infrastructure based on a slightly hacked up logger. Instead of the traditional "if debug { ... }" I've rewritten the logger to have no-op Debugln and Debugf, unless debugging has been enabled for a given "facility". The "facility" is just a string, typically a package name. This will be slightly slower than before; but not that much as it's mostly a function call that returns immediately. For the cases where it matters (the Debugln takes a hex.Dump() of something for example, and it's not in a very occasional "if err != nil" branch) there is an l.ShouldDebug(facility) that is fast enough to be used like the old "if debug". The point of all this is that we can now toggle debugging for the various packages on and off at runtime. There's a new method /rest/system/debug that can be POSTed a set of facilities to enable and disable debug for, or GET from to get a list of facilities with descriptions and their current debug status. Similarly a /rest/system/log?since=... can grab the latest log entries, up to 250 of them (hardcoded constant in main.go) plus the initial few. Not implemented in this commit (but planned) is a simple debug GUI available on /debug that shows the current log in an easily pasteable format and has checkboxes to enable the various debug facilities. The debug instructions to a user then becomes "visit this URL, check these boxes, reproduce your problem, copy and paste the log". The actual log viewer on the hypothetical /debug URL can poll regularly for new log entries and this bypass the 250 line limit. The existing STTRACE=foo variable is still obeyed and just sets the start state of the system.
2015-10-03 15:25:21 +00:00
"github.com/syncthing/syncthing/lib/logger"
)
const (
logThreshold = 100 * time.Millisecond
shortWait = 5 * time.Millisecond
longWait = 125 * time.Millisecond
)
func TestTypes(t *testing.T) {
2015-04-24 00:43:40 +00:00
debug = false
Implement facility based logger, debugging via REST API This implements a new debug/trace infrastructure based on a slightly hacked up logger. Instead of the traditional "if debug { ... }" I've rewritten the logger to have no-op Debugln and Debugf, unless debugging has been enabled for a given "facility". The "facility" is just a string, typically a package name. This will be slightly slower than before; but not that much as it's mostly a function call that returns immediately. For the cases where it matters (the Debugln takes a hex.Dump() of something for example, and it's not in a very occasional "if err != nil" branch) there is an l.ShouldDebug(facility) that is fast enough to be used like the old "if debug". The point of all this is that we can now toggle debugging for the various packages on and off at runtime. There's a new method /rest/system/debug that can be POSTed a set of facilities to enable and disable debug for, or GET from to get a list of facilities with descriptions and their current debug status. Similarly a /rest/system/log?since=... can grab the latest log entries, up to 250 of them (hardcoded constant in main.go) plus the initial few. Not implemented in this commit (but planned) is a simple debug GUI available on /debug that shows the current log in an easily pasteable format and has checkboxes to enable the various debug facilities. The debug instructions to a user then becomes "visit this URL, check these boxes, reproduce your problem, copy and paste the log". The actual log viewer on the hypothetical /debug URL can poll regularly for new log entries and this bypass the 250 line limit. The existing STTRACE=foo variable is still obeyed and just sets the start state of the system.
2015-10-03 15:25:21 +00:00
l.SetDebug("sync", false)
2015-04-24 00:43:40 +00:00
if _, ok := NewMutex().(*sync.Mutex); !ok {
t.Error("Wrong type")
}
if _, ok := NewRWMutex().(*sync.RWMutex); !ok {
t.Error("Wrong type")
}
if _, ok := NewWaitGroup().(*sync.WaitGroup); !ok {
t.Error("Wrong type")
}
debug = true
Implement facility based logger, debugging via REST API This implements a new debug/trace infrastructure based on a slightly hacked up logger. Instead of the traditional "if debug { ... }" I've rewritten the logger to have no-op Debugln and Debugf, unless debugging has been enabled for a given "facility". The "facility" is just a string, typically a package name. This will be slightly slower than before; but not that much as it's mostly a function call that returns immediately. For the cases where it matters (the Debugln takes a hex.Dump() of something for example, and it's not in a very occasional "if err != nil" branch) there is an l.ShouldDebug(facility) that is fast enough to be used like the old "if debug". The point of all this is that we can now toggle debugging for the various packages on and off at runtime. There's a new method /rest/system/debug that can be POSTed a set of facilities to enable and disable debug for, or GET from to get a list of facilities with descriptions and their current debug status. Similarly a /rest/system/log?since=... can grab the latest log entries, up to 250 of them (hardcoded constant in main.go) plus the initial few. Not implemented in this commit (but planned) is a simple debug GUI available on /debug that shows the current log in an easily pasteable format and has checkboxes to enable the various debug facilities. The debug instructions to a user then becomes "visit this URL, check these boxes, reproduce your problem, copy and paste the log". The actual log viewer on the hypothetical /debug URL can poll regularly for new log entries and this bypass the 250 line limit. The existing STTRACE=foo variable is still obeyed and just sets the start state of the system.
2015-10-03 15:25:21 +00:00
l.SetDebug("sync", true)
if _, ok := NewMutex().(*loggedMutex); !ok {
t.Error("Wrong type")
}
if _, ok := NewRWMutex().(*loggedRWMutex); !ok {
t.Error("Wrong type")
}
if _, ok := NewWaitGroup().(*loggedWaitGroup); !ok {
t.Error("Wrong type")
}
debug = false
Implement facility based logger, debugging via REST API This implements a new debug/trace infrastructure based on a slightly hacked up logger. Instead of the traditional "if debug { ... }" I've rewritten the logger to have no-op Debugln and Debugf, unless debugging has been enabled for a given "facility". The "facility" is just a string, typically a package name. This will be slightly slower than before; but not that much as it's mostly a function call that returns immediately. For the cases where it matters (the Debugln takes a hex.Dump() of something for example, and it's not in a very occasional "if err != nil" branch) there is an l.ShouldDebug(facility) that is fast enough to be used like the old "if debug". The point of all this is that we can now toggle debugging for the various packages on and off at runtime. There's a new method /rest/system/debug that can be POSTed a set of facilities to enable and disable debug for, or GET from to get a list of facilities with descriptions and their current debug status. Similarly a /rest/system/log?since=... can grab the latest log entries, up to 250 of them (hardcoded constant in main.go) plus the initial few. Not implemented in this commit (but planned) is a simple debug GUI available on /debug that shows the current log in an easily pasteable format and has checkboxes to enable the various debug facilities. The debug instructions to a user then becomes "visit this URL, check these boxes, reproduce your problem, copy and paste the log". The actual log viewer on the hypothetical /debug URL can poll regularly for new log entries and this bypass the 250 line limit. The existing STTRACE=foo variable is still obeyed and just sets the start state of the system.
2015-10-03 15:25:21 +00:00
l.SetDebug("sync", false)
}
func TestMutex(t *testing.T) {
oldClock := defaultClock
clock := newTestClock()
defaultClock = clock
defer func() { defaultClock = oldClock }()
debug = true
Implement facility based logger, debugging via REST API This implements a new debug/trace infrastructure based on a slightly hacked up logger. Instead of the traditional "if debug { ... }" I've rewritten the logger to have no-op Debugln and Debugf, unless debugging has been enabled for a given "facility". The "facility" is just a string, typically a package name. This will be slightly slower than before; but not that much as it's mostly a function call that returns immediately. For the cases where it matters (the Debugln takes a hex.Dump() of something for example, and it's not in a very occasional "if err != nil" branch) there is an l.ShouldDebug(facility) that is fast enough to be used like the old "if debug". The point of all this is that we can now toggle debugging for the various packages on and off at runtime. There's a new method /rest/system/debug that can be POSTed a set of facilities to enable and disable debug for, or GET from to get a list of facilities with descriptions and their current debug status. Similarly a /rest/system/log?since=... can grab the latest log entries, up to 250 of them (hardcoded constant in main.go) plus the initial few. Not implemented in this commit (but planned) is a simple debug GUI available on /debug that shows the current log in an easily pasteable format and has checkboxes to enable the various debug facilities. The debug instructions to a user then becomes "visit this URL, check these boxes, reproduce your problem, copy and paste the log". The actual log viewer on the hypothetical /debug URL can poll regularly for new log entries and this bypass the 250 line limit. The existing STTRACE=foo variable is still obeyed and just sets the start state of the system.
2015-10-03 15:25:21 +00:00
l.SetDebug("sync", true)
threshold = logThreshold
msgmut := sync.Mutex{}
2015-04-28 20:32:10 +00:00
var messages []string
l.AddHandler(logger.LevelDebug, func(_ logger.LogLevel, message string) {
msgmut.Lock()
messages = append(messages, message)
msgmut.Unlock()
})
mut := NewMutex()
mut.Lock()
clock.wind(shortWait)
mut.Unlock()
if len(messages) > 0 {
t.Errorf("Unexpected message count")
}
mut.Lock()
clock.wind(longWait)
mut.Unlock()
if len(messages) != 1 {
t.Errorf("Unexpected message count")
}
debug = false
Implement facility based logger, debugging via REST API This implements a new debug/trace infrastructure based on a slightly hacked up logger. Instead of the traditional "if debug { ... }" I've rewritten the logger to have no-op Debugln and Debugf, unless debugging has been enabled for a given "facility". The "facility" is just a string, typically a package name. This will be slightly slower than before; but not that much as it's mostly a function call that returns immediately. For the cases where it matters (the Debugln takes a hex.Dump() of something for example, and it's not in a very occasional "if err != nil" branch) there is an l.ShouldDebug(facility) that is fast enough to be used like the old "if debug". The point of all this is that we can now toggle debugging for the various packages on and off at runtime. There's a new method /rest/system/debug that can be POSTed a set of facilities to enable and disable debug for, or GET from to get a list of facilities with descriptions and their current debug status. Similarly a /rest/system/log?since=... can grab the latest log entries, up to 250 of them (hardcoded constant in main.go) plus the initial few. Not implemented in this commit (but planned) is a simple debug GUI available on /debug that shows the current log in an easily pasteable format and has checkboxes to enable the various debug facilities. The debug instructions to a user then becomes "visit this URL, check these boxes, reproduce your problem, copy and paste the log". The actual log viewer on the hypothetical /debug URL can poll regularly for new log entries and this bypass the 250 line limit. The existing STTRACE=foo variable is still obeyed and just sets the start state of the system.
2015-10-03 15:25:21 +00:00
l.SetDebug("sync", false)
}
func TestRWMutex(t *testing.T) {
oldClock := defaultClock
clock := newTestClock()
defaultClock = clock
defer func() { defaultClock = oldClock }()
debug = true
Implement facility based logger, debugging via REST API This implements a new debug/trace infrastructure based on a slightly hacked up logger. Instead of the traditional "if debug { ... }" I've rewritten the logger to have no-op Debugln and Debugf, unless debugging has been enabled for a given "facility". The "facility" is just a string, typically a package name. This will be slightly slower than before; but not that much as it's mostly a function call that returns immediately. For the cases where it matters (the Debugln takes a hex.Dump() of something for example, and it's not in a very occasional "if err != nil" branch) there is an l.ShouldDebug(facility) that is fast enough to be used like the old "if debug". The point of all this is that we can now toggle debugging for the various packages on and off at runtime. There's a new method /rest/system/debug that can be POSTed a set of facilities to enable and disable debug for, or GET from to get a list of facilities with descriptions and their current debug status. Similarly a /rest/system/log?since=... can grab the latest log entries, up to 250 of them (hardcoded constant in main.go) plus the initial few. Not implemented in this commit (but planned) is a simple debug GUI available on /debug that shows the current log in an easily pasteable format and has checkboxes to enable the various debug facilities. The debug instructions to a user then becomes "visit this URL, check these boxes, reproduce your problem, copy and paste the log". The actual log viewer on the hypothetical /debug URL can poll regularly for new log entries and this bypass the 250 line limit. The existing STTRACE=foo variable is still obeyed and just sets the start state of the system.
2015-10-03 15:25:21 +00:00
l.SetDebug("sync", true)
threshold = logThreshold
msgmut := sync.Mutex{}
2015-04-28 20:32:10 +00:00
var messages []string
l.AddHandler(logger.LevelDebug, func(_ logger.LogLevel, message string) {
msgmut.Lock()
messages = append(messages, message)
msgmut.Unlock()
})
mut := NewRWMutex()
mut.Lock()
clock.wind(shortWait)
mut.Unlock()
if len(messages) > 0 {
t.Errorf("Unexpected message count")
}
mut.Lock()
clock.wind(longWait)
mut.Unlock()
if len(messages) != 1 {
t.Errorf("Unexpected message count")
}
// Testing rlocker logging
wait := make(chan struct{})
locking := make(chan struct{})
mut.RLock()
go func() {
close(locking)
mut.Lock()
close(wait)
}()
<-locking
clock.wind(longWait)
mut.RUnlock()
<-wait
mut.Unlock()
if len(messages) != 2 {
t.Errorf("Unexpected message count")
} else if !strings.Contains(messages[1], "RUnlockers while locking:\nat sync") || !strings.Contains(messages[1], "sync_test.go:") {
t.Error("Unexpected message")
}
// Testing multiple rlockers
mut.RLock()
mut.RLock()
mut.RLock()
_ = 1 // skip empty critical section check
mut.RUnlock()
mut.RUnlock()
mut.RUnlock()
debug = false
Implement facility based logger, debugging via REST API This implements a new debug/trace infrastructure based on a slightly hacked up logger. Instead of the traditional "if debug { ... }" I've rewritten the logger to have no-op Debugln and Debugf, unless debugging has been enabled for a given "facility". The "facility" is just a string, typically a package name. This will be slightly slower than before; but not that much as it's mostly a function call that returns immediately. For the cases where it matters (the Debugln takes a hex.Dump() of something for example, and it's not in a very occasional "if err != nil" branch) there is an l.ShouldDebug(facility) that is fast enough to be used like the old "if debug". The point of all this is that we can now toggle debugging for the various packages on and off at runtime. There's a new method /rest/system/debug that can be POSTed a set of facilities to enable and disable debug for, or GET from to get a list of facilities with descriptions and their current debug status. Similarly a /rest/system/log?since=... can grab the latest log entries, up to 250 of them (hardcoded constant in main.go) plus the initial few. Not implemented in this commit (but planned) is a simple debug GUI available on /debug that shows the current log in an easily pasteable format and has checkboxes to enable the various debug facilities. The debug instructions to a user then becomes "visit this URL, check these boxes, reproduce your problem, copy and paste the log". The actual log viewer on the hypothetical /debug URL can poll regularly for new log entries and this bypass the 250 line limit. The existing STTRACE=foo variable is still obeyed and just sets the start state of the system.
2015-10-03 15:25:21 +00:00
l.SetDebug("sync", false)
}
func TestWaitGroup(t *testing.T) {
oldClock := defaultClock
clock := newTestClock()
defaultClock = clock
defer func() { defaultClock = oldClock }()
debug = true
Implement facility based logger, debugging via REST API This implements a new debug/trace infrastructure based on a slightly hacked up logger. Instead of the traditional "if debug { ... }" I've rewritten the logger to have no-op Debugln and Debugf, unless debugging has been enabled for a given "facility". The "facility" is just a string, typically a package name. This will be slightly slower than before; but not that much as it's mostly a function call that returns immediately. For the cases where it matters (the Debugln takes a hex.Dump() of something for example, and it's not in a very occasional "if err != nil" branch) there is an l.ShouldDebug(facility) that is fast enough to be used like the old "if debug". The point of all this is that we can now toggle debugging for the various packages on and off at runtime. There's a new method /rest/system/debug that can be POSTed a set of facilities to enable and disable debug for, or GET from to get a list of facilities with descriptions and their current debug status. Similarly a /rest/system/log?since=... can grab the latest log entries, up to 250 of them (hardcoded constant in main.go) plus the initial few. Not implemented in this commit (but planned) is a simple debug GUI available on /debug that shows the current log in an easily pasteable format and has checkboxes to enable the various debug facilities. The debug instructions to a user then becomes "visit this URL, check these boxes, reproduce your problem, copy and paste the log". The actual log viewer on the hypothetical /debug URL can poll regularly for new log entries and this bypass the 250 line limit. The existing STTRACE=foo variable is still obeyed and just sets the start state of the system.
2015-10-03 15:25:21 +00:00
l.SetDebug("sync", true)
threshold = logThreshold
msgmut := sync.Mutex{}
2015-04-28 20:32:10 +00:00
var messages []string
l.AddHandler(logger.LevelDebug, func(_ logger.LogLevel, message string) {
msgmut.Lock()
messages = append(messages, message)
msgmut.Unlock()
})
wg := NewWaitGroup()
wg.Add(1)
waiting := make(chan struct{})
go func() {
<-waiting
clock.wind(shortWait)
wg.Done()
}()
close(waiting)
wg.Wait()
if len(messages) > 0 {
t.Errorf("Unexpected message count")
}
wg = NewWaitGroup()
waiting = make(chan struct{})
wg.Add(1)
go func() {
<-waiting
clock.wind(longWait)
wg.Done()
}()
close(waiting)
wg.Wait()
if len(messages) != 1 {
t.Errorf("Unexpected message count")
}
debug = false
Implement facility based logger, debugging via REST API This implements a new debug/trace infrastructure based on a slightly hacked up logger. Instead of the traditional "if debug { ... }" I've rewritten the logger to have no-op Debugln and Debugf, unless debugging has been enabled for a given "facility". The "facility" is just a string, typically a package name. This will be slightly slower than before; but not that much as it's mostly a function call that returns immediately. For the cases where it matters (the Debugln takes a hex.Dump() of something for example, and it's not in a very occasional "if err != nil" branch) there is an l.ShouldDebug(facility) that is fast enough to be used like the old "if debug". The point of all this is that we can now toggle debugging for the various packages on and off at runtime. There's a new method /rest/system/debug that can be POSTed a set of facilities to enable and disable debug for, or GET from to get a list of facilities with descriptions and their current debug status. Similarly a /rest/system/log?since=... can grab the latest log entries, up to 250 of them (hardcoded constant in main.go) plus the initial few. Not implemented in this commit (but planned) is a simple debug GUI available on /debug that shows the current log in an easily pasteable format and has checkboxes to enable the various debug facilities. The debug instructions to a user then becomes "visit this URL, check these boxes, reproduce your problem, copy and paste the log". The actual log viewer on the hypothetical /debug URL can poll regularly for new log entries and this bypass the 250 line limit. The existing STTRACE=foo variable is still obeyed and just sets the start state of the system.
2015-10-03 15:25:21 +00:00
l.SetDebug("sync", false)
}
func TestTimeoutCond(t *testing.T) {
// WARNING this test relies heavily on threads not being stalled at particular points.
// As such, it's pretty unstable on the build server. It has been left in as it still
// exercises the deadlock detector, and one of the two things it tests is still functional.
// See the comments in runLocks
const (
// Low values to avoid being intrusive in continuous testing. Can be
// increased significantly for stress testing.
iterations = 100
routines = 10
timeMult = 2
)
c := NewTimeoutCond(NewMutex())
// Start a routine to periodically broadcast on the cond.
go func() {
d := time.Duration(routines) * timeMult * time.Millisecond / 2
t.Log("Broadcasting every", d)
for i := 0; i < iterations; i++ {
time.Sleep(d)
c.L.Lock()
c.Broadcast()
c.L.Unlock()
}
}()
// Start several routines that wait on it with different timeouts.
var results [routines][2]int
var wg sync.WaitGroup
for i := 0; i < routines; i++ {
i := i
wg.Add(1)
go func() {
d := time.Duration(i) * timeMult * time.Millisecond
t.Logf("Routine %d waits for %v\n", i, d)
succ, fail := runLocks(t, iterations, c, d)
results[i][0] = succ
results[i][1] = fail
wg.Done()
}()
}
wg.Wait()
// Print a table of routine number: successes, failures.
for i, v := range results {
t.Logf("%4d: %4d %4d\n", i, v[0], v[1])
}
}
func runLocks(t *testing.T, iterations int, c *TimeoutCond, d time.Duration) (succ, fail int) {
for i := 0; i < iterations; i++ {
c.L.Lock()
// The thread may be stalled, so we can't test the 'succeeded late' case reliably.
// Therefore make sure that we start t0 before starting the timeout, and only test
// the 'failed early' case.
t0 := time.Now()
w := c.SetupWait(d)
res := w.Wait()
waited := time.Since(t0)
// Allow 20% slide in either direction, and a five milliseconds of
// scheduling delay... In tweaking these it was clear that things
// worked like the should, so if this becomes a spurious failure
// kind of thing feel free to remove or give significantly more
// slack.
if !res && waited < d*8/10 {
t.Errorf("Wait failed early, %v < %v", waited, d)
}
if res && waited > d*11/10+5*time.Millisecond {
// Ideally this would be t.Errorf
t.Logf("WARNING: Wait succeeded late, %v > %v. This is probably a thread scheduling issue", waited, d)
}
w.Stop()
if res {
succ++
} else {
fail++
}
c.L.Unlock()
}
return
}
type testClock struct {
time time.Time
mut sync.Mutex
}
func newTestClock() *testClock {
return &testClock{
time: time.Now(),
}
}
func (t *testClock) Now() time.Time {
t.mut.Lock()
now := t.time
t.time = t.time.Add(time.Nanosecond)
t.mut.Unlock()
return now
}
func (t *testClock) wind(d time.Duration) {
t.mut.Lock()
t.time = t.time.Add(d)
t.mut.Unlock()
}