Threadsafe logging

pkg/log/counter.go

@@ -0,0 +1,31 @@
+package log
+
+import "sync"
+
+type counter struct {
+	mu   sync.RWMutex
+	seen map[string]int
+}
+
+func newCounter() *counter {
+	return &counter{seen: map[string]int{}}
+}
+
+func (ctr *counter) count(key string) int {
+	ctr.mu.Lock()
+	defer ctr.mu.Unlock()
+	return ctr.seen[key]
+}
+
+func (ctr *counter) delete(key string) {
+	ctr.mu.Lock()
+	delete(ctr.seen, key)
+	ctr.mu.Unlock()
+}
+
+func (ctr *counter) increment(key string) int {
+	ctr.mu.Lock()
+	defer ctr.mu.Unlock()
+	ctr.seen[key]++
+	return ctr.seen[key]
+}

pkg/log/counter_test.go

@@ -0,0 +1,68 @@
+package log
+
+import (
+	"sync"
+	"testing"
+)
+
+func TestCounter_Ops(t *testing.T) {
+	ctr := newCounter()
+
+	var num int
+
+	// Should return 0 if never seen
+	num = ctr.count("something")
+	if num != 0 {
+		t.Fatalf("counter: count: expected %d; found %d", 0, num)
+	}
+
+	// Should return 1 if seen once
+	num = ctr.increment("something")
+	if num != 1 {
+		t.Fatalf("counter: count: expected %d; found %d", 1, num)
+	}
+
+	// Should still return 1 if seen only once
+	num = ctr.count("something")
+	if num != 1 {
+		t.Fatalf("counter: count: expected %d; found %d", 1, num)
+	}
+
+	// Should return 1 if seen once
+	for i := 2; i <= 234; i++ {
+		num = ctr.increment("something")
+		if num != i {
+			t.Fatalf("counter: count: expected %d; found %d", i, num)
+		}
+	}
+
+	ctr.delete("something")
+	num = ctr.count("something")
+	if num != 0 {
+		t.Fatalf("counter: count: expected %d; found %d", 0, num)
+	}
+}
+
+func TestCounter_Threadsafety(t *testing.T) {
+	var wg sync.WaitGroup
+
+	// Run 1000 goroutines, logging 10000 times each as fast as they can
+	for i := 1; i <= 1000; i++ {
+		wg.Add(1)
+		go func() {
+			for j := 1; j <= 10000; j++ {
+				DedupedInfof(10, "this log seen %d times", j)
+			}
+			wg.Done()
+		}()
+	}
+
+	wg.Wait()
+}
+
+func TestDeduping(t *testing.T) {
+	// Should log 10 times, then stop
+	for i := 1; i <= 234; i++ {
+		DedupedInfof(10, "this log seen %d times", i)
+	}
+}

pkg/log/log.go

@@ -7,26 +7,25 @@ import (
 	"k8s.io/klog"
 )
 
-var seen = make(map[string]int)
+// concurrency-safe counter
+var ctr = newCounter()
 
 func Errorf(format string, a ...interface{}) {
 	klog.Errorf(fmt.Sprintf("[Error] %s", format), a...)
 }
 
 func DedupedErrorf(logTypeLimit int, format string, a ...interface{}) {
-	timesLogged, ok := seen[format]
-	if !ok {
-		seen[format] = 1
+	timesLogged := ctr.increment(format)
+
+	if timesLogged < logTypeLimit {
+		Errorf(format, a...)
 	} else if timesLogged == logTypeLimit {
-		seen[format]++
-		f := fmt.Sprintf("[Error] %s", format)
-		klog.Errorf("%s seen %d times, suppressing future logs", f, logTypeLimit)
-	} else if timesLogged > logTypeLimit {
-		seen[format]++
-	} else {
-		seen[format]++
-		klog.Errorf(fmt.Sprintf("[Error] %s", format), a...)
+		Errorf(format, a...)
+		Infof("%s logged %d times: suppressing future logs", format, logTypeLimit)
 	}
+
+	// TODO if timeLogged > logTypeLimit, log once every... 100 (?) times so we
+	// don't lose track entirely?
 }
 
 func Warningf(format string, a ...interface{}) {
@@ -34,19 +33,17 @@ func Warningf(format string, a ...interface{}) {
 }
 
 func DedupedWarningf(logTypeLimit int, format string, a ...interface{}) {
-	timesLogged, ok := seen[format]
-	if !ok {
-		seen[format] = 1
+	timesLogged := ctr.increment(format)
+
+	if timesLogged < logTypeLimit {
+		Warningf(format, a...)
 	} else if timesLogged == logTypeLimit {
-		seen[format]++
-		f := fmt.Sprintf("[Warning] %s", format)
-		klog.Errorf("%s seen %d times, suppressing future logs", f, logTypeLimit)
-	} else if timesLogged > logTypeLimit {
-		seen[format]++
-	} else {
-		seen[format]++
-		klog.V(2).Infof(fmt.Sprintf("[Warning] %s", format), a...)
+		Warningf(format, a...)
+		Infof("%s logged %d times: suppressing future logs", format, logTypeLimit)
 	}
+
+	// TODO if timeLogged > logTypeLimit, log once every... 100 (?) times so we
+	// don't lose track entirely?
 }
 
 func Infof(format string, a ...interface{}) {
@@ -54,19 +51,17 @@ func Infof(format string, a ...interface{}) {
 }
 
 func DedupedInfof(logTypeLimit int, format string, a ...interface{}) {
-	timesLogged, ok := seen[format]
-	if !ok {
-		seen[format] = 1
+	timesLogged := ctr.increment(format)
+
+	if timesLogged < logTypeLimit {
+		Infof(format, a...)
 	} else if timesLogged == logTypeLimit {
-		seen[format]++
-		f := fmt.Sprintf("[Info] %s", format)
-		klog.Errorf("%s seen %d times, suppressing future logs", f, logTypeLimit)
-	} else if timesLogged > logTypeLimit {
-		seen[format]++
-	} else {
-		seen[format]++
-		klog.V(3).Infof(fmt.Sprintf("[Info] %s", format), a...)
+		Infof(format, a...)
+		Infof("%s logged %d times: suppressing future logs", format, logTypeLimit)
 	}
+
+	// TODO if timeLogged > logTypeLimit, log once every... 100 (?) times so we
+	// don't lose track entirely?
 }
 
 func Profilef(format string, a ...interface{}) {