go-algorand 3.13.2-beta Release PR

buildnumber.dat

@@ -1 +1 @@
-1
+2

logging/cyclicWriter.go

@@ -21,6 +21,7 @@ import (
 	"os"
 	"os/exec"
 	"path/filepath"
+	"runtime"
 	"strings"
 	"text/template"
 	"time"
@@ -124,6 +125,16 @@ func (cyclic *CyclicFileWriter) Write(p []byte) (n int, err error) {
 
 	if uint64(len(p)) > cyclic.limit {
 		// there's no hope for writing this entry to the log
+
+		// for the large lines this is a clear indication something does wrong, dump data into stderr
+		const minDebugLogLineSize = 10 * 1024 * 1024
+		if len(p) >= minDebugLogLineSize {
+			buf := make([]byte, 16*1024)
+			stlen := runtime.Stack(buf, false)
+			fmt.Fprintf(os.Stderr, "Attempt to write a large log line:\n%s\n", string(buf[:stlen]))
+			fmt.Fprintf(os.Stderr, "The offending line:\n%s\n", string(p[:4096]))
+		}
+
 		return 0, fmt.Errorf("CyclicFileWriter: input too long to write. Len = %v", len(p))
 	}
 

logging/telemetryhook.go

@@ -26,7 +26,8 @@ import (
 	"github.com/algorand/go-algorand/util/metrics"
 )
 
-var telemetryDrops = metrics.MakeCounter(metrics.MetricName{Name: "algod_telemetry_drops_total", Description: "telemetry messages not sent to server"})
+var telemetryDrops = metrics.MakeCounter(metrics.MetricName{Name: "algod_telemetry_drops_total", Description: "telemetry messages dropped due to full queues"})
+var telemetryErrors = metrics.MakeCounter(metrics.MetricName{Name: "algod_telemetry_errs_total", Description: "telemetry messages dropped due to server error"})
 
 func createAsyncHook(wrappedHook logrus.Hook, channelDepth uint, maxQueueDepth int) *asyncTelemetryHook {
 	return createAsyncHookLevels(wrappedHook, channelDepth, maxQueueDepth, makeLevels(logrus.InfoLevel))
@@ -88,7 +89,8 @@ func createAsyncHookLevels(wrappedHook logrus.Hook, channelDepth uint, maxQueueD
 					if entry != nil {
 						err := hook.wrappedHook.Fire(entry)
 						if err != nil {
-							Base().Warnf("Unable to write event %#v to telemetry : %v", entry, err)
+							Base().WithFields(Fields{"TelemetryError": true}).Warnf("Unable to write event %#v to telemetry : %v", entry, err)
+							telemetryErrors.Inc(nil)
 						}
 						hook.wg.Done()
 					} else {
@@ -146,6 +148,9 @@ func (hook *asyncTelemetryHook) waitForEventAndReady() bool {
 
 // Fire is required to implement logrus hook interface
 func (hook *asyncTelemetryHook) Fire(entry *logrus.Entry) error {
+	if _, ok := entry.Data["TelemetryError"]; ok {
+		return nil
+	}
 	hook.wg.Add(1)
 	select {
 	case <-hook.quit:

logging/telemetryhook_test.go

@@ -229,3 +229,34 @@ func TestAsyncTelemetryHook_QueueDepth(t *testing.T) {
 	// be one higher then the maxDepth.
 	require.LessOrEqual(t, hookEntries, maxDepth+1)
 }
+
+// Ensure that errors from inside the telemetryhook.go implementation are not reported to telemetry.
+func TestAsyncTelemetryHook_SelfReporting(t *testing.T) {
+	partitiontest.PartitionTest(t)
+	t.Parallel()
+
+	const entryCount = 100
+	const maxDepth = 10
+
+	filling := make(chan struct{})
+
+	testHook := makeMockTelemetryHook(logrus.DebugLevel)
+	testHook.cb = func(entry *logrus.Entry) {
+		<-filling // Block while filling
+	}
+
+	hook := createAsyncHook(&testHook, 100, 10)
+	hook.ready = true
+	for i := 0; i < entryCount; i++ {
+		selfEntry := logrus.Entry{
+			Level:   logrus.ErrorLevel,
+			Data:    logrus.Fields{"TelemetryError": true},
+			Message: "Unable to write event",
+		}
+		hook.Fire(&selfEntry)
+	}
+	close(filling)
+	hook.Close()
+
+	require.Len(t, testHook.entries(), 0)
+}