Add JSON logger, update middleware to all follow same pattern

Author: sbecker

main.go

@@ -5,18 +5,24 @@ import (
 	"github.com/sbecker/gin-api-demo/dao"
 	"github.com/sbecker/gin-api-demo/middleware"
 	"github.com/sbecker/gin-api-demo/resources"
+	"github.com/sbecker/gin-api-demo/util"
 )
 
 func main() {
 	dao.InitDb()
 
-	r := gin.Default()
-	r.Use(middleware.RequestID)
-	r.Use(middleware.Auth)
-	r.Use(middleware.CORS)
+	util.UseJSONLogFormat()
+	gin.SetMode(gin.ReleaseMode)
 
-	r.GET("/users", resources.GetAllUsers)
-	r.GET("/users/:id", resources.GetUserByID)
+	r := gin.New()
+
+	r.Use(middleware.JSONLogMiddleware())
+	r.Use(gin.Recovery())
+	r.Use(middleware.RequestID(middleware.RequestIDOptions{AllowSetting: false}))
+	r.Use(middleware.Auth())
+	r.Use(middleware.CORS(middleware.CORSOptions{}))
+
+	resources.NewUserResource(r)
 
 	r.Run(":8080") // listen and serve on 0.0.0.0:8080
 }

middleware/auth.go

@@ -7,29 +7,32 @@ import (
 	"github.com/sbecker/gin-api-demo/dao"
 )
 
-func Auth(c *gin.Context) {
-	authHeader := c.Request.Header.Get("Authorization")
-	r, _ := regexp.Compile("^Bearer (.+)$")
-
-	match := r.FindStringSubmatch(authHeader)
-
-	if len(match) == 0 {
-		c.AbortWithStatus(401)
-		return
-	}
-	tokenString := match[1]
-
-	if len(tokenString) == 0 {
-		c.AbortWithStatus(401)
-		return
+func Auth() gin.HandlerFunc {
+	return func(c *gin.Context) {
+		authHeader := c.Request.Header.Get("Authorization")
+		r, _ := regexp.Compile("^Bearer (.+)$")
+
+		match := r.FindStringSubmatch(authHeader)
+
+		if len(match) == 0 {
+			c.AbortWithStatus(401)
+			return
+		}
+		tokenString := match[1]
+
+		if len(tokenString) == 0 {
+			c.AbortWithStatus(401)
+			return
+		}
+
+		user, err := dao.GetUserByAuthToken(tokenString)
+		if err != nil {
+			c.AbortWithStatus(401)
+			return
+		}
+
+		c.Set("user", user)
+		c.Set("userID", user.ID)
+		c.Next()
 	}
-
-	user, err := dao.GetUserByAuthToken(tokenString)
-	if err != nil {
-		c.AbortWithStatus(401)
-		return
-	}
-
-	c.Set("currentUser", user)
-	c.Next()
 }

middleware/cors.go

@@ -2,19 +2,27 @@ package middleware
 
 import "github.com/gin-gonic/gin"
 
+type CORSOptions struct {
+	Origin string
+}
+
 // CORS middleware from https://github.com/gin-gonic/gin/issues/29#issuecomment-89132826
-func CORS(c *gin.Context) {
-	c.Writer.Header().Set("Access-Control-Allow-Origin", "*") // allow any origin domain
-	// c.Writer.Header().Set("Access-Control-Allow-Origin", "http://domain.com") // uncomment to restrict to single domain
-	c.Writer.Header().Set("Access-Control-Max-Age", "86400")
-	c.Writer.Header().Set("Access-Control-Allow-Methods", "POST, GET, OPTIONS, PUT, DELETE, UPDATE")
-	c.Writer.Header().Set("Access-Control-Allow-Headers", "Origin, Content-Type, Content-Length, Accept-Encoding, X-CSRF-Token, Authorization")
-	c.Writer.Header().Set("Access-Control-Expose-Headers", "Content-Length")
-	c.Writer.Header().Set("Access-Control-Allow-Credentials", "true")
+func CORS(options CORSOptions) gin.HandlerFunc {
+	return func(c *gin.Context) {
+		c.Writer.Header().Set("Access-Control-Allow-Origin", "*") // allow any origin domain
+		if options.Origin != "" {
+			c.Writer.Header().Set("Access-Control-Allow-Origin", options.Origin)
+		}
+		c.Writer.Header().Set("Access-Control-Max-Age", "86400")
+		c.Writer.Header().Set("Access-Control-Allow-Methods", "POST, GET, OPTIONS, PUT, DELETE, UPDATE")
+		c.Writer.Header().Set("Access-Control-Allow-Headers", "Origin, Content-Type, Content-Length, Accept-Encoding, X-CSRF-Token, Authorization")
+		c.Writer.Header().Set("Access-Control-Expose-Headers", "Content-Length")
+		c.Writer.Header().Set("Access-Control-Allow-Credentials", "true")
 
-	if c.Request.Method == "OPTIONS" {
-		c.AbortWithStatus(200)
-	} else {
-		c.Next()
+		if c.Request.Method == "OPTIONS" {
+			c.AbortWithStatus(200)
+		} else {
+			c.Next()
+		}
 	}
 }

middleware/json_logger.go

@@ -0,0 +1,41 @@
+package middleware
+
+import (
+	"time"
+
+	log "github.com/Sirupsen/logrus"
+	"github.com/gin-gonic/gin"
+	"github.com/sbecker/gin-api-demo/util"
+)
+
+// JSONLogMiddleware logs a gin HTTP request in JSON format, with some additional custom key/values
+func JSONLogMiddleware() gin.HandlerFunc {
+	return func(c *gin.Context) {
+		// Start timer
+		start := time.Now()
+
+		// Process Request
+		c.Next()
+
+		// Stop timer
+		duration := util.GetDurationInMillseconds(start)
+
+		entry := log.WithFields(log.Fields{
+			"client_ip":  util.GetClientIP(c),
+			"duration":   duration,
+			"method":     c.Request.Method,
+			"path":       c.Request.RequestURI,
+			"status":     c.Writer.Status(),
+			"user_id":    util.GetUserID(c),
+			"referrer":   c.Request.Referer(),
+			"request_id": c.Writer.Header().Get("Request-Id"),
+			// "api_version": util.ApiVersion,
+		})
+
+		if c.Writer.Status() >= 500 {
+			entry.Error(c.Errors.String())
+		} else {
+			entry.Info("")
+		}
+	}
+}

middleware/request_id.go

@@ -5,13 +5,25 @@ import (
 	"github.com/pborman/uuid"
 )
 
-func RequestID(c *gin.Context) {
-	// If Set-Request-Id header is set on request, use that for
-	// Request-Id response header. Otherwise, generate a new one.
-	requestID := c.Request.Header.Get("Set-Request-Id")
-	if requestID == "" {
-		requestID = uuid.New()
+type RequestIDOptions struct {
+	AllowSetting bool
+}
+
+func RequestID(options RequestIDOptions) gin.HandlerFunc {
+	return func(c *gin.Context) {
+		var requestID string
+
+		if options.AllowSetting {
+			// If Set-Request-Id header is set on request, use that for
+			// Request-Id response header. Otherwise, generate a new one.
+			requestID = c.Request.Header.Get("Set-Request-Id")
+		}
+
+		if requestID == "" {
+			requestID = uuid.New()
+		}
+
+		c.Writer.Header().Set("Request-Id", requestID)
+		c.Next()
 	}
-	c.Writer.Header().Set("Request-Id", requestID)
-	c.Next()
 }

resources/helper.go

@@ -23,5 +23,5 @@ func getStringParam(c *gin.Context, name string) (string, error) {
 }
 
 func getCurrentUser(c *gin.Context) models.User {
-	return c.MustGet("currentUser").(models.User)
+	return c.MustGet("user").(models.User)
 }

resources/user_resource.go

@@ -6,13 +6,24 @@ import (
 	"github.com/sbecker/gin-api-demo/serializers"
 )
 
-func GetAllUsers(c *gin.Context) {
+type UserResource struct {
+}
+
+func NewUserResource(e *gin.Engine) {
+	u := UserResource{}
+
+	// Setup Routes
+	e.GET("/users", u.getAllUsers)
+	e.GET("/users/:id", u.getUserByID)
+}
+
+func (r *UserResource) getAllUsers(c *gin.Context) {
 	currentUser := getCurrentUser(c)
 	users := dao.GetAllUsers(currentUser)
 	c.JSON(200, serializers.SerializeUsers(users, currentUser, "/users"))
 }
 
-func GetUserByID(c *gin.Context) {
+func (r *UserResource) getUserByID(c *gin.Context) {
 	currentUser := getCurrentUser(c)
 
 	id, err := getStringParam(c, "id")

util/env.go

@@ -0,0 +1,12 @@
+package util
+
+import "os"
+
+func GetEnv(key, defaultValue string) string {
+	value := os.Getenv(key)
+	if value != "" {
+		return value
+	}
+
+	return defaultValue
+}

util/log.go

@@ -0,0 +1,94 @@
+package util
+
+import (
+	"encoding/json"
+	"fmt"
+	"strings"
+	"time"
+
+	log "github.com/Sirupsen/logrus"
+	"github.com/gin-gonic/gin"
+	"github.com/thedataguild/faer/util"
+)
+
+// UseJSONLogFormat sets up the JSON log formatter
+func UseJSONLogFormat() {
+	env := util.GetEnv("GIN_ENV", "development")
+	program := util.GetEnv("SERVICE_NAME", "gin-api-demo")
+
+	log.SetFormatter(&JSONFormatter{
+		Program: program,
+		Env:     env,
+	})
+
+	// so our debug entries appear!
+	log.SetLevel(log.DebugLevel)
+}
+
+// Timestamps in microsecond resolution (like time.RFC3339Nano but microseconds)
+var timeStampFormat = "2006-01-02T15:04:05.000000Z07:00"
+
+// JSONFormatter is a logger for use with Logrus
+type JSONFormatter struct {
+	Program string
+	Env     string
+}
+
+// Format includes the program, environment, and a custom time format: microsecond resolution
+func (f *JSONFormatter) Format(entry *log.Entry) ([]byte, error) {
+	data := make(log.Fields, len(entry.Data)+3)
+	for k, v := range entry.Data {
+		data[k] = v
+	}
+	data["time"] = entry.Time.UTC().Format(timeStampFormat)
+	data["msg"] = entry.Message
+	data["level"] = strings.ToUpper(entry.Level.String())
+	data["program"] = f.Program
+	data["env"] = f.Env
+
+	serialized, err := json.Marshal(data)
+	if err != nil {
+		return nil, fmt.Errorf("Failed to marshal fields to JSON, %v", err)
+	}
+	return append(serialized, '\n'), nil
+}
+
+// clientIP gets the correct IP for the end client instead of the proxy
+func GetClientIP(c *gin.Context) string {
+	// first check the X-Forwarded-For header
+	requester := c.Request.Header.Get("X-Forwarded-For")
+	// if empty, check the Real-IP header
+	if len(requester) == 0 {
+		requester = c.Request.Header.Get("X-Real-IP")
+	}
+	// if the requester is still empty, use the hard-coded address from the socket
+	if len(requester) == 0 {
+		requester = c.Request.RemoteAddr
+	}
+
+	// if requester is a comma delimited list, take the first one
+	// (this happens when proxied via elastic load balancer then again through nginx)
+	if strings.Contains(requester, ",") {
+		requester = strings.Split(requester, ",")[0]
+	}
+
+	return requester
+}
+
+// getUserID gets the current_user ID as a string
+func GetUserID(c *gin.Context) string {
+	userID, exists := c.Get("userID")
+	if exists {
+		return userID.(string)
+	}
+	return ""
+}
+
+// gets the duration of time since "start", in milliseconds
+func GetDurationInMillseconds(start time.Time) float64 {
+	end := time.Now()
+	duration := end.Sub(start)
+	milliseconds := float64(duration) / float64(time.Millisecond)
+	rounded := float64(int(milliseconds*100+.5)) / 100
+	return rounded
+}