Thread Safetey appears to be working with immutable logic added

Author: nmccready

debug.go

@@ -38,7 +38,7 @@ type Debugger struct {
 	prev   time.Time
 	fields Fields
 	color  string
-	mu     MutexWrap
+	// mu     MutexWrap
 }
 
 type IDebugger interface {
@@ -223,35 +223,39 @@ var SetHasTime = setBoolWithLock(func(isOn bool) {
 	HAS_TIME = isOn
 })
 
+func (dbg Debugger) ApplyRootFields(name string) Debugger {
+	if formatter.GetHasFieldsOnly() {
+		dbg = *dbg.WithFields(map[string]interface{}{"namespace": name})
+
+		if HAS_TIME {
+			dbg = *dbg.WithFields(map[string]interface{}{"time": nil, "delta": nil})
+		}
+	}
+	return dbg
+}
+
 // Debug creates a debug function for `name` which you call
 // with printf-style arguments in your application or library.
-func Debug(name string) *Debugger {
+func Debug(name string) Debugger {
 	entry, cached := cache.Get(name)
 
 	if cached {
 		dbg, _ := entry.(Debugger)
-		return &dbg
+		return dbg.ApplyRootFields(name)
 	}
 
 	dbg := Debugger{name: name, prev: time.Now(), color: colors[rand.Intn(len(colors))]}
-
-	if formatter.GetHasFieldsOnly() {
-		dbg.WithFields(map[string]interface{}{"namespace": name})
-
-		if HAS_TIME {
-			dbg.WithFields(map[string]interface{}{"time": nil, "delta": nil})
-		}
-	}
+	dbg = dbg.ApplyRootFields(name)
 
 	cache.Set(name, dbg, goCache.DefaultExpiration)
 
-	return &dbg
+	return dbg
 }
 
-func (dbg *Debugger) Spawn(ns string) *Debugger {
+func (dbg Debugger) Spawn(ns string) *Debugger {
 	d := Debug(dbg.name + ":" + ns)
 	d.fields = dbg.fields
-	return d
+	return &d
 }
 
 func (dbg *Debugger) Log(args ...interface{}) {
@@ -269,8 +273,7 @@ func (dbg *Debugger) Log(args ...interface{}) {
 		}
 	}
 
-	dbg.mu.Lock()
-
+	// dbg.mu.Lock()
 	var msg interface{}
 
 	if len(args) >= 1 {
@@ -296,49 +299,46 @@ func (dbg *Debugger) Log(args ...interface{}) {
 		}
 	}
 
-	preppedMsg := formatter.Format(dbg, msg)
-	dbg.mu.Unlock()
-
+	m.Lock()
+	preppedMsg := formatter.Format(*dbg, msg)
 	fmt.Fprintf(writer, preppedMsg, args...)
+	m.Unlock()
 	dbg.prev = time.Now()
 }
 
 // prepend error/warn name as it is easier to filter!
-func (dbg *Debugger) Error(args ...interface{}) {
+func (dbg Debugger) Error(args ...interface{}) {
 	d := Debug("error:" + dbg.name)
 	d.fields = dbg.fields
 	d.Log(args...)
 }
-func (dbg *Debugger) Warn(args ...interface{}) {
+func (dbg Debugger) Warn(args ...interface{}) {
 	d := Debug("warn:" + dbg.name)
 	d.fields = dbg.fields
 	d.Log(args...)
 }
 
-func (dbg *Debugger) WithFields(fields map[string]interface{}) *Debugger {
-	dbg.mu.Lock()
+// NOT *Debugger receiver on purpose to be immutable to not deal with locks on fields
+func (dbg Debugger) WithFields(fields map[string]interface{}) *Debugger {
 	if len(dbg.fields) == 0 {
 		dbg.fields = fields
-		dbg.mu.Unlock()
-		return dbg
+		return &dbg
 	}
 
 	for k, v := range fields {
 		dbg.fields[k] = v
 	}
-	dbg.mu.Unlock()
-	return dbg
+	return &dbg
 }
 
-func (dbg *Debugger) WithField(key string, value interface{}) *Debugger {
-	dbg.mu.Lock()
+// NOT *Debugger receiver on purpose to be immutable to not deal with locks on fields
+func (dbg Debugger) WithField(key string, value interface{}) *Debugger {
 	if len(dbg.fields) == 0 {
 		dbg.fields = map[string]interface{}{}
 	}
 
 	dbg.fields[key] = value
-	dbg.mu.Unlock()
-	return dbg
+	return &dbg
 }
 
 func getColorStr(color string, isOn bool) string {
@@ -391,24 +391,3 @@ func humanizeNano(n int64) string {
 
 	return strconv.Itoa(int(n)) + suffix
 }
-
-type MutexWrap struct {
-	lock     sync.Mutex
-	disabled bool
-}
-
-func (mw *MutexWrap) Lock() {
-	if !mw.disabled {
-		mw.lock.Lock()
-	}
-}
-
-func (mw *MutexWrap) Unlock() {
-	if !mw.disabled {
-		mw.lock.Unlock()
-	}
-}
-
-func (mw *MutexWrap) Disable() {
-	mw.disabled = true
-}

debug_thread_test.go

@@ -0,0 +1,59 @@
+package debug
+
+import (
+	"bytes"
+	"strconv"
+	"sync"
+	"testing"
+)
+
+func TestThreadSafety(t *testing.T) {
+	debug := Debug("foo")
+	var b []byte
+	buf := bytes.NewBuffer(b)
+	SetWriter(buf)
+	Enable("*")
+
+	wg := sync.WaitGroup{}
+	totalThreads := 8000
+	wg.Add(totalThreads)
+
+	for i := 0; i < totalThreads; i++ {
+		i := i
+		go func() {
+			defer wg.Done()
+			f := Fields{}
+			f[strconv.Itoa(i)] = "test"
+			debug.Spawn("thread" + strconv.Itoa(i)).WithFields(f).Log("something")
+		}()
+	}
+	wg.Wait()
+}
+
+func TestThreadJsonSafety(t *testing.T) {
+	debug := Debug("foo")
+	SetFormatter(&JSONFormatter{})
+	var b []byte
+	buf := bytes.NewBuffer(b)
+	SetWriter(buf)
+	Enable("*")
+
+	wg := sync.WaitGroup{}
+	totalThreads := 1000
+	wg.Add(totalThreads)
+
+	for i := 0; i < totalThreads; i++ {
+		i := i
+		go func() {
+			defer wg.Done()
+			f := Fields{}
+			f[strconv.Itoa(i)] = "test"
+			f["a"] = "test"
+			f["b"] = "test"
+			f["c"] = "test"
+			f["d"] = "test"
+			debug.Spawn("thread" + strconv.Itoa(i)).WithFields(f).Log("something")
+		}()
+	}
+	wg.Wait()
+}

formatter.go

@@ -15,7 +15,7 @@ const (
 
 // highly inspired by logrus
 type Formatter interface {
-	Format(*Debugger, interface{}) string
+	Format(Debugger, interface{}) string
 	GetHasFieldsOnly() bool
 }
 
@@ -28,7 +28,7 @@ type TextFormatter struct {
 	SortingFunc      func(keys []string)
 }
 
-func (t *TextFormatter) Format(dbg *Debugger, _msg interface{}) string {
+func (t *TextFormatter) Format(dbg Debugger, _msg interface{}) string {
 	msg, didCast := _msg.(string)
 	if !didCast {
 		msg = fmt.Sprintf("%+v", _msg)
@@ -132,7 +132,7 @@ type Finalized struct {
 }
 
 func finalizeFields(
-	dbg *Debugger, msg string, hasColor bool, flattenMsg bool, cb func(string, interface{}) interface{}) *Finalized {
+	dbg Debugger, msg string, hasColor bool, flattenMsg bool, cb func(string, interface{}) interface{}) *Finalized {
 	ts, delta := deltas(dbg.prev)
 	ns := getColorStr(dbg.color, hasColor) + dbg.name + getColorOff(hasColor)
 

formatter_test.go

@@ -8,10 +8,11 @@ import (
 	"github.com/stretchr/testify/assert"
 )
 
-func TestTextFormatterFieldSpawnMultipleEnabled(t *testing.T) {
+func TestTextFormatterFieldSpawnMultipleEnabledText(t *testing.T) {
 	var b []byte
 	buf := bytes.NewBuffer(b)
 	SetWriter(buf)
+	SetFormatterString("text")
 
 	Enable("foo*,bar*")
 
@@ -40,10 +41,47 @@ func TestTextFormatterFieldSpawnMultipleEnabled(t *testing.T) {
 	assert.Contains(t, str, "bar lazy")
 }
 
+func TestTextFormatterFieldSpawnMultipleEnabledJSON(t *testing.T) {
+	var b []byte
+	buf := bytes.NewBuffer(b)
+	SetWriter(buf)
+	SetFormatterString("json")
+
+	Enable("foo*,bar*")
+
+	foo := Debug("foo").Spawn("child").Spawn("grandChild").WithFields(
+		Fields{"field": 1, "field2": "two", "field3": "multiple strings"})
+	foo.Log("foo")
+	foo.Log(func() string { return "foo lazy" })
+
+	bar := Debug("bar").Spawn("child").Spawn("grandChild")
+	bar.Log("bar")
+	bar.Log(func() string { return "bar lazy" })
+
+	if buf.Len() == 0 {
+		t.Fatalf("buffer should have output")
+	}
+
+	str := buf.String()
+	// fmt.Println(str)
+	assert.Contains(t, str, `"field": 1`)
+	assert.Contains(t, str, `"field2": "two"`)
+	assert.Contains(t, str, `"field3": "multiple strings"`)
+
+	assert.Contains(t, str, `"msg": "foo"`)
+	assert.Contains(t, str, `"msg": "foo lazy"`)
+	assert.Contains(t, str, `"msg": "bar"`)
+	assert.Contains(t, str, `"msg": "bar lazy"`)
+	// namespaces exist
+	assert.Contains(t, str, "foo:child:grandChild", "namespace")
+	// assert.Contains(t, str, "bar:child:grandChild")
+}
+
 func TestBasicTextFormatterFieldsStrict(t *testing.T) {
 	var b []byte
 	buf := bytes.NewBuffer(b)
 	SetWriter(buf)
+	SetFormatterString("text")
 
 	Enable("foo*")
 

json_formatter.go

@@ -45,7 +45,7 @@ type JSONFormatter struct {
 	FlattenMsgFields bool
 }
 
-func (f *JSONFormatter) Format(dbg *Debugger, _msg interface{}) string {
+func (f *JSONFormatter) Format(dbg Debugger, _msg interface{}) string {
 	var msg string
 	var msgFields *Fields
 

json_formatter_test.go

@@ -13,7 +13,7 @@ func TestErrorNotLost(t *testing.T) {
 	SetHasColors(false)
 	SetFormatter(&JSONFormatter{})
 
-	s := formatter.Format(Debug("error_not_lost").WithField("error", errors.New("wild walrus")), "hi")
+	s := formatter.Format(*Debug("error_not_lost").WithField("error", errors.New("wild walrus")), "hi")
 
 	entry := make(map[string]interface{})
 	err := json.Unmarshal([]byte(s), &entry)
@@ -31,7 +31,7 @@ func TestErrorNotLostOnFieldNotNamedError(t *testing.T) {
 	SetHasColors(false)
 	SetFormatter(&JSONFormatter{})
 
-	s := formatter.Format(Debug("mapped_field_error").WithField("omg", errors.New("wild walrus")), "hi")
+	s := formatter.Format(*Debug("mapped_field_error").WithField("omg", errors.New("wild walrus")), "hi")
 
 	entry := make(map[string]interface{})
 	err := json.Unmarshal([]byte(s), &entry)
@@ -49,7 +49,7 @@ func TestFieldClashWithTime(t *testing.T) {
 	SetHasColors(false)
 	SetFormatter(&JSONFormatter{})
 
-	s := formatter.Format(Debug("clash_time").WithField("time", "right now!"), "hi")
+	s := formatter.Format(*Debug("clash_time").WithField("time", "right now!"), "hi")
 
 	entry := make(map[string]interface{})
 	err := json.Unmarshal([]byte(s), &entry)
@@ -66,7 +66,7 @@ func TestFieldClashWithMsg(t *testing.T) {
 	SetHasColors(false)
 	SetFormatter(&JSONFormatter{})
 
-	s := formatter.Format(Debug("clash_msg").WithField("msg", errors.New("wild walrus")), "hi")
+	s := formatter.Format(*Debug("clash_msg").WithField("msg", errors.New("wild walrus")), "hi")
 
 	entry := make(map[string]interface{})
 	err := json.Unmarshal([]byte(s), &entry)
@@ -79,7 +79,7 @@ func TestFieldClashWithNamespace(t *testing.T) {
 	SetHasColors(false)
 	SetFormatter(&JSONFormatter{})
 
-	s := formatter.Format(Debug("clash_namespace").WithField("namespace", errors.New("wild walrus")), "hi")
+	s := formatter.Format(*Debug("clash_namespace").WithField("namespace", errors.New("wild walrus")), "hi")
 
 	entry := make(map[string]interface{})
 	err := json.Unmarshal([]byte(s), &entry)
@@ -91,7 +91,7 @@ func TestFieldClashWithNamespace(t *testing.T) {
 func TestJSONEntryEndsWithNewline(t *testing.T) {
 	SetFormatter(&JSONFormatter{})
 
-	s := formatter.Format(Debug("newline").WithField("dog", errors.New("wild walrus")), "hi")
+	s := formatter.Format(*Debug("newline").WithField("dog", errors.New("wild walrus")), "hi")
 
 	entry := make(map[string]interface{})
 	err := json.Unmarshal([]byte(s), &entry)
@@ -105,7 +105,7 @@ func TestJSONPretty(t *testing.T) {
 	SetHasColors(false)
 	SetFormatter(&JSONFormatter{PrettyPrint: true})
 
-	s := formatter.Format(Debug("pretty").WithField("dog", "wild walrus"), "hi")
+	s := formatter.Format(*Debug("pretty").WithField("dog", "wild walrus"), "hi")
 	expected := "{\n  \"dog\": \"wild walrus\",\n  \"msg\": \"hi\",\n  \"namespace\": \"pretty\"\n}\n"
 
 	assert.Equal(t, expected, s, "is pretty")