feat: Improve log messages to be more informative (#1322)

## Which problem is this PR solving?

Improve some log messages to be more accurate about what's actually
happening.

- closes #1321

## Short description of the changes
- Improve log messages
- Prefer using WithField / WithString to include parameters instead of
inline formatting
- Update memory overrun messages from error -> warn - they do not
constitute data lost so error feels heavy handed

---------

Co-authored-by: Kent Quirk <kentquirk@honeycomb.io>

cmd/refinery/main.go

@@ -334,5 +334,5 @@ func main() {
 	// unregister ourselves before we go
 	close(done)
 	time.Sleep(100 * time.Millisecond)
-	a.Logger.Error().Logf("Caught signal \"%s\"", sig)
+	a.Logger.Error().WithField("signal", sig).Logf("Caught OS signal")
 }

collect/collect.go

@@ -30,7 +30,7 @@ import (
 	"github.com/sirupsen/logrus"
 )
 
-var ErrWouldBlock = errors.New("not adding span, channel buffer is full")
+var ErrWouldBlock = errors.New("Dropping span as channel buffer is full. Span will not be processed and will be lost.")
 var CollectorHealthKey = "collector"
 
 type Collector interface {
@@ -265,13 +265,13 @@ func (i *InMemCollector) checkAlloc() {
 	i.cache.RemoveTraces(tracesSent)
 
 	// Treat any MaxAlloc overage as an error so we know it's happening
-	i.Logger.Error().
+	i.Logger.Warn().
 		WithField("cache_size", cap).
 		WithField("alloc", mem.Alloc).
 		WithField("num_traces_sent", len(tracesSent)).
 		WithField("datasize_sent", totalDataSizeSent).
 		WithField("new_trace_count", i.cache.GetCacheCapacity()).
-		Logf("evicting large traces early due to memory overage")
+		Logf("Making some trace decisions early due to memory overrun.")
 
 	// Manually GC here - without this we can easily end up evicting more than we
 	// need to, since total alloc won't be updated until after a GC pass.
@@ -797,7 +797,7 @@ func (i *InMemCollector) send(trace *types.Trace, sendReason string) {
 	// if we're supposed to drop this trace, and dry run mode is not enabled, then we're done.
 	if !shouldSend && !i.Config.GetIsDryRun() {
 		i.Metrics.Increment("trace_send_dropped")
-		i.Logger.Info().WithFields(logFields).Logf("Dropping trace because of sampling")
+		i.Logger.Info().WithFields(logFields).Logf("Dropping trace because of sampling decision")
 		return
 	}
 	i.Metrics.Increment("trace_send_kept")
@@ -806,9 +806,10 @@ func (i *InMemCollector) send(trace *types.Trace, sendReason string) {
 
 	// ok, we're not dropping this trace; send all the spans
 	if i.Config.GetIsDryRun() && !shouldSend {
-		i.Logger.Info().WithFields(logFields).Logf("Trace would have been dropped, but dry run mode is enabled")
+		i.Logger.Info().WithFields(logFields).Logf("Trace would have been dropped, but sending because dry run mode is enabled")
+	} else {
+		i.Logger.Info().WithFields(logFields).Logf("Sending trace")
 	}
-	i.Logger.Info().WithFields(logFields).Logf("Sending trace")
 	for _, sp := range trace.GetSpans() {
 		if i.Config.GetAddRuleReasonToTrace() {
 			sp.Data["meta.refinery.reason"] = reason

collect/stressRelief.go

@@ -255,7 +255,7 @@ func (s *StressRelief) UpdateFromConfig(cfg config.StressReliefConfig) {
 		s.mode = Always
 	default: // validation shouldn't let this happen but we'll be safe...
 		s.mode = Never
-		s.Logger.Error().Logf("StressRelief mode is '%s' which shouldn't happen", cfg.Mode)
+		s.Logger.Error().WithString("mode", cfg.Mode).Logf("Invalid StressRelief mode")
 	}
 	s.Logger.Debug().WithField("mode", s.mode).Logf("setting StressRelief mode")
 

metrics/otel_metrics.go

@@ -189,7 +189,7 @@ func (o *OTelMetrics) Register(name string, metricType string) {
 	case "counter":
 		ctr, err := o.meter.Int64Counter(name)
 		if err != nil {
-			o.Logger.Error().WithString("msg", "failed to create counter").WithString("name", name)
+			o.Logger.Error().WithString("name", name).Logf("failed to create counter")
 			return
 		}
 		o.counters[name] = ctr
@@ -210,26 +210,26 @@ func (o *OTelMetrics) Register(name string, metricType string) {
 			metric.WithFloat64Callback(f),
 		)
 		if err != nil {
-			o.Logger.Error().WithString("msg", "failed to create gauge").WithString("name", name)
+			o.Logger.Error().WithString("name", name).Logf("failed to create gauge")
 			return
 		}
 		o.gauges[name] = g
 	case "histogram":
 		h, err := o.meter.Float64Histogram(name)
 		if err != nil {
-			o.Logger.Error().WithString("msg", "failed to create histogram").WithString("name", name)
+			o.Logger.Error().WithString("name", name).Logf("failed to create histogram")
 			return
 		}
 		o.histograms[name] = h
 	case "updown":
 		ud, err := o.meter.Int64UpDownCounter(name)
 		if err != nil {
-			o.Logger.Error().WithString("msg", "failed to create updown").WithString("name", name)
+			o.Logger.Error().WithString("name", name).Logf("failed to create updown counter")
 			return
 		}
 		o.updowns[name] = ud
 	default:
-		o.Logger.Error().WithString("msg", "unknown metric type").WithString("type", metricType)
+		o.Logger.Error().WithString("type", metricType).Logf("unknown metric type")
 		return
 	}
 }

sharder/deterministic.go

@@ -133,7 +133,7 @@ func (d *DeterministicSharder) Start() error {
 		time.Sleep(5 * time.Second)
 	}
 
-	d.Logger.Error().WithFields(map[string]interface{}{"peers": d.peers, "self": self}).Logf("list of current peers")
+	d.Logger.Error().WithFields(map[string]interface{}{"peers": d.peers, "self": self}).Logf("failed to find self in the peer list")
 	return errors.New("failed to find self in the peer list")
 }