Add observability utilities (#10312)

.github/CODEOWNERS

@@ -213,6 +213,8 @@ Dockerfile @sourcegraph/distribution
 /internal/redispool/ @keegancsmith
 /internal/store/ @keegancsmith
 /internal/metrics @keegancsmith @slimsag
+/internal/logging @keegancsmith @slimsag
+/internal/observation @keegancsmith @slimsag
 
 # Code discussions
 **/*discussion* @slimsag

internal/logging/logging.go

@@ -7,7 +7,7 @@ type ErrorLogger interface {
 
 // Log logs the given message and context when the given error is defined.
 func Log(lg ErrorLogger, msg string, err *error, ctx ...interface{}) {
-	if err == nil || *err == nil {
+	if lg == nil || err == nil || *err == nil {
 		return
 	}
 

internal/metrics/operation.go

@@ -34,28 +34,61 @@ func (m *OperationMetrics) MustRegister(r prometheus.Registerer) {
 	r.MustRegister(m.Errors)
 }
 
-// NewOperationMetrics creates an OperationMetrics value without any
-// specific labels. The supplied operationName should be underscore_cased
-// as it is used in the metric name.
-func NewOperationMetrics(subsystem, metricPrefix, operationName string) *OperationMetrics {
+type operationMetricOptions struct {
+	durationHelp string
+	countHelp    string
+	errorsHelp   string
+}
+
+// OperationMetricsOption alter the default behavior of NewOperationMetrics.
+type OperationMetricsOption func(o *operationMetricOptions)
+
+// WithDurationHelp overrides the default help text for duration metrics.
+func WithDurationHelp(text string) OperationMetricsOption {
+	return func(o *operationMetricOptions) { o.durationHelp = text }
+}
+
+// WithCountHelp overrides the default help text for count metrics.
+func WithCountHelp(text string) OperationMetricsOption {
+	return func(o *operationMetricOptions) { o.countHelp = text }
+}
+
+// WithErrorsHelp overrides the default help text for errors metrics.
+func WithErrorsHelp(text string) OperationMetricsOption {
+	return func(o *operationMetricOptions) { o.errorsHelp = text }
+}
+
+// NewOperationMetrics creates an OperationMetrics value. The supplied operationName should
+// be underscore_cased as it is used in the metric name.
+func NewOperationMetrics(subsystem, metricPrefix, operationName string, fns ...OperationMetricsOption) *OperationMetrics {
+	options := &operationMetricOptions{
+		durationHelp: fmt.Sprintf("Time in seconds spent performing %s operations", operationName),
+		countHelp:    fmt.Sprintf("Total number of %s operations", operationName),
+		errorsHelp:   fmt.Sprintf("Total number of errors when performing %s operations", operationName),
+	}
+
+	for _, fn := range fns {
+		fn(options)
+	}
+
 	return &OperationMetrics{
 		Duration: prometheus.NewHistogramVec(prometheus.HistogramOpts{
 			Namespace: "src",
 			Subsystem: subsystem,
 			Name:      fmt.Sprintf("%s_%s_duration_seconds", metricPrefix, operationName),
-			Help:      "Time spent performing %s operations",
+			Help:      options.durationHelp,
 		}, []string{}),
 		Count: prometheus.NewCounterVec(prometheus.CounterOpts{
 			Namespace: "src",
 			Subsystem: subsystem,
 			Name:      fmt.Sprintf("%s_%s_total", metricPrefix, operationName),
-			Help:      fmt.Sprintf("Total number of %s operations", operationName),
+			Help:      options.countHelp,
 		}, []string{}),
 		Errors: prometheus.NewCounterVec(prometheus.CounterOpts{
 			Namespace: "src",
 			Subsystem: subsystem,
 			Name:      fmt.Sprintf("%s_%s_errors_total", metricPrefix, operationName),
-			Help:      fmt.Sprintf("Total number of errors when performing %s operations", operationName),
+			Help:      options.errorsHelp,
 		}, []string{}),
 	}
 }

internal/observation/observation.go

@@ -0,0 +1,110 @@
+package observation
+
+import (
+	"context"
+	"time"
+
+	"github.com/opentracing/opentracing-go/log"
+	"github.com/sourcegraph/sourcegraph/internal/logging"
+	"github.com/sourcegraph/sourcegraph/internal/metrics"
+	"github.com/sourcegraph/sourcegraph/internal/trace"
+)
+
+// Args are the arguments to the With function.
+type Args struct {
+	Logger  logging.ErrorLogger
+	Metrics *metrics.OperationMetrics
+	Tracer  *trace.Tracer
+	// Err is a pointer to the operation's err result.
+	Err       *error
+	TraceName string
+	LogName   string
+	// LogFields are logged prior to the operation being performed.
+	LogFields []log.Field
+}
+
+// FinishFn is the shape of the function returned by With and should be
+// invoked within a defer directly before the observed function returns.
+type FinishFn func(
+	// The number of things processed.
+	count float64,
+	// Fields to log after the operation is performed.
+	additionalLogFields ...log.Field,
+)
+
+// With prepares the necessary timers, loggers, and metrics to observe an
+// operation.
+//
+// If your function does not process a variable number of items and the
+// counting metric counts invocations, the method should be deferred as follows:
+//
+//     func observedFoo(ctx context.Context) (err error) {
+//         ctx, finish := observation.With(ctx, observation.Args{
+//             Err: &err,
+//             Logger: logger,
+//             Metrics: metrics,
+//             Tracer: tracer,
+//             TraceName: "TraceName",
+//             LogName: "log-name"
+//         })
+//         defer finish(1)
+//
+//         return realFoo()
+//     }
+//
+// If the function processes a variable number of items which are known only after the
+// operation completes, the method should be deferred as follows:
+//
+//     func observedFoo(ctx context.Context) (items []Foo err error) {
+//         ctx, finish := observation.With(ctx, observation.Args{
+//             Err: &err,
+//             Logger: logger,
+//             Metrics: metrics,
+//             Tracer: tracer,
+//             TraceName: "TraceName",
+//             LogName: "log-name"
+//         })
+//         defer func() {
+//             finish(float64(len(items)))
+//         }()
+//
+//         return realFoo()
+//     }
+//
+// The finish function can be supplied a variable number of log fields which will be logged
+// in the trace and when an error occurs.
+func With(ctx context.Context, args Args) (context.Context, FinishFn) {
+	began := time.Now()
+
+	var tr *trace.Trace
+	if args.Tracer != nil {
+		tr, ctx = args.Tracer.New(ctx, args.TraceName, "")
+		tr.LogFields(args.LogFields...)
+	}
+
+	return ctx, func(count float64, additionalLogFields ...log.Field) {
+		elapsed := time.Since(began).Seconds()
+
+		logFields := append(append(append(
+			make([]log.Field, 0, len(args.LogFields)+len(additionalLogFields)+1),
+			args.LogFields...),
+			log.Float64("count", count)),
+			additionalLogFields...,
+		)
+		kvs := make([]interface{}, 0, len(logFields)*2)
+		for _, field := range logFields {
+			kvs = append(kvs, field.Key(), field.Value())
+		}
+
+		args.Metrics.Observe(elapsed, count, args.Err)
+		logging.Log(args.Logger, args.LogName, args.Err, kvs...)
+
+		if tr != nil {
+			tr.LogFields(logFields...)
+			if args.Err != nil {
+				tr.SetError(*args.Err)
+			}
+			tr.Finish()
+		}
+	}
+}

internal/observation/observation_test.go

@@ -0,0 +1,12 @@
+package observation
+
+import (
+	"context"
+	"testing"
+)
+
+// Ensure we don't have a nil panic when some optional value is not supplied.
+func TestWithMissingItems(t *testing.T) {
+	_, finish := With(context.Background(), Args{})
+	finish(0)
+}