Monitor how long take requests to process with a beego filter using logrus for structured output

beego_monitor_filter.go

package filters

import (
	"time"

	"github.com/Sirupsen/logrus"
	"github.com/astaxie/beego"
	"github.com/astaxie/beego/context"
	uuid "github.com/hashicorp/go-uuid"
)

const (
	timeKey      = "REQUEST_INIT_TIME"
	requestIDKey = "REQUEST_ID"
	pathKey      = "PATH"
)

var logger = logrus.WithField("op", "monitor")

// Monitor performs performance monitoring from the
// path forward.
func Monitor(path string) {
	beego.InsertFilter(path, beego.BeforeRouter, setRequestTime)
	beego.InsertFilter(path, beego.AfterExec, logRequestTime)
}

func setRequestTime(ctx *context.Context) {
	rid, err := uuid.GenerateUUID()
	if err != nil {
		logger.Infof("Failed to generate request UUID: %s", err)
		return
	}
	now := time.Now()
	log(ctx.Request.URL.Path, rid, "Processing at %s", now.Format(time.RFC3339Nano))
	ctx.Input.SetData(timeKey, now)
	ctx.Input.SetData(requestIDKey, rid)
}

func logRequestTime(ctx *context.Context) {
	rid, ok := ctx.Input.GetData(requestIDKey).(string)
	previous, ok := ctx.Input.GetData(timeKey).(time.Time)
	if !ok {
		logger.Info("Data in Ctx has been tampered with")
		return
	}
	log(ctx.Request.URL.Path, rid, "Took %d miliseconds to end", time.Now().Sub(previous)*time.Millisecond)
}

func log(path, rid, format string, args ...interface{}) {
	logger.WithFields(logrus.Fields{
		requestIDKey: rid,
		pathKey:      path,
	}).Infof(format, args)
}