Merge pull request #283 from movio/name-event

Include operation type and name in log message

instrumentation.go

@@ -11,7 +11,7 @@ import (
 const eventKey contextKey = "instrumentation"
 
 type event struct {
-	name      string
+	nameFunc  EventNameFunc
 	timestamp time.Time
 	fields    EventFields
 	fieldLock sync.Mutex
@@ -21,15 +21,18 @@ type event struct {
 // EventFields contains fields to be logged for the event
 type EventFields map[string]interface{}
 
-func newEvent(name string) *event {
+// EventNameFunc constructs a name for the event from the provided fields
+type EventNameFunc func(EventFields) string
+
+func newEvent(name EventNameFunc) *event {
 	return &event{
-		name:      name,
+		nameFunc:  name,
 		timestamp: time.Now(),
 		fields:    EventFields{},
 	}
 }
 
-func startEvent(ctx context.Context, name string) (context.Context, *event) {
+func startEvent(ctx context.Context, name EventNameFunc) (context.Context, *event) {
 	ev := newEvent(name)
 	return context.WithValue(ctx, eventKey, ev), ev
 }
@@ -52,7 +55,7 @@ func (e *event) finish() {
 	e.writeLock.Do(func() {
 		log.WithField("duration", time.Since(e.timestamp).String()).
 			WithFields(log.Fields(e.fields)).
-			Info(e.name)
+			Info(e.nameFunc(e.fields))
 	})
 }
 

instrumentation_test.go

@@ -54,13 +54,17 @@ func collectEventFromContext(ctx context.Context, t *testing.T, f func(*event))
 	})
 }
 
+func testEventName(EventFields) string {
+	return "test"
+}
+
 func TestDropsField(t *testing.T) {
 	AddField(context.TODO(), "val", "test")
 	assert.True(t, true)
 }
 
 func TestEventLogOnFinish(t *testing.T) {
-	ctx, _ := startEvent(context.TODO(), "test")
+	ctx, _ := startEvent(context.TODO(), testEventName)
 	output := collectEventFromContext(ctx, t, func(*event) {
 		AddField(ctx, "val", "test")
 	})
@@ -69,7 +73,7 @@ func TestEventLogOnFinish(t *testing.T) {
 }
 
 func TestAddMultipleToEventOnContext(t *testing.T) {
-	ctx, _ := startEvent(context.TODO(), "test")
+	ctx, _ := startEvent(context.TODO(), testEventName)
 	output := collectEventFromContext(ctx, t, func(*event) {
 		AddFields(ctx, EventFields{
 			"gizmo":   "foo",
@@ -83,7 +87,7 @@ func TestAddMultipleToEventOnContext(t *testing.T) {
 
 func TestEventMeasurement(t *testing.T) {
 	start := time.Now()
-	ctx, _ := startEvent(context.TODO(), "test")
+	ctx, _ := startEvent(context.TODO(), testEventName)
 	output := collectEventFromContext(ctx, t, func(*event) {
 		time.Sleep(time.Microsecond)
 	})

middleware.go

@@ -63,7 +63,7 @@ func debugMiddleware(h http.Handler) http.Handler {
 
 func monitoringMiddleware(h http.Handler) http.Handler {
 	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-		ctx, event := startEvent(r.Context(), "request")
+		ctx, event := startEvent(r.Context(), nameMonitoringEvent)
 		if !strings.HasPrefix(r.Header.Get("user-agent"), "Bramble") {
 			defer event.finish()
 		}
@@ -101,6 +101,16 @@ func monitoringMiddleware(h http.Handler) http.Handler {
 	})
 }
 
+func nameMonitoringEvent(fields EventFields) string {
+	if t := fields["operation.type"]; t != nil {
+		if n := fields["operation.name"]; n != "" {
+			return fmt.Sprintf("%s:%s", t, n)
+		}
+		return fmt.Sprintf("%s", t)
+	}
+	return "request"
+}
+
 func addRequestBody(e *event, r *http.Request, buf bytes.Buffer) {
 	contentType, _, _ := mime.ParseMediaType(r.Header.Get("Content-Type"))
 	e.addField("request.content-type", contentType)