Merge pull request #2 from PereRohit/feat/logger-server-enhancement

Logger with caller + default request id for incoming requests

constant/constant.go

@@ -14,3 +14,7 @@ var (
 const (
 	HealthRoute = "/health"
 )
+
+const (
+	RequestIdHeader = "request_id"
+)

go.mod

@@ -7,6 +7,7 @@ require github.com/go-playground/validator/v10 v10.11.0
 require (
 	github.com/go-playground/locales v0.14.0 // indirect
 	github.com/go-playground/universal-translator v0.18.0 // indirect
+	github.com/google/uuid v1.3.0 // indirect
 	github.com/leodido/go-urn v1.2.1 // indirect
 	golang.org/x/crypto v0.0.0-20211215153901-e495a2d5b3d3 // indirect
 	golang.org/x/sys v0.0.0-20210806184541-e5e7981a1069 // indirect

go.sum

@@ -10,6 +10,8 @@ github.com/go-playground/universal-translator v0.18.0 h1:82dyy6p4OuJq4/CByFNOn/j
 github.com/go-playground/universal-translator v0.18.0/go.mod h1:UvRDBj+xPUEGrFYl+lu/H90nyDXpg0fqeB/AQUGNTVA=
 github.com/go-playground/validator/v10 v10.11.0 h1:0W+xRM511GY47Yy3bZUbJVitCNg2BOGlCyvTqsp/xIw=
 github.com/go-playground/validator/v10 v10.11.0/go.mod h1:i+3WkQ1FvaUjjxh1kSvIA4dMGDBiPU55YFDl0WbKdWU=
+github.com/google/uuid v1.3.0 h1:t6JiXgmwXMjEs8VusXIJk2BXHsn+wx8BZdTaoZ5fu7I=
+github.com/google/uuid v1.3.0/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo=
 github.com/kr/pretty v0.1.0/go.mod h1:dAy3ld7l9f0ibDNOQOHHMYYIIbhfbHSm3C4ZsoJORNo=
 github.com/kr/pretty v0.2.1/go.mod h1:ipq/a2n7PKx3OHsz4KJII5eveXtPO4qwEXGdVfWzfnI=
 github.com/kr/pretty v0.3.0/go.mod h1:640gp4NfQd8pI5XOwp5fnNeVWj67G7CFk/SaSQn7NBk=

log/logger.go

@@ -1,8 +1,12 @@
 package log
 
 import (
+	"fmt"
 	"log"
 	"os"
+	"path/filepath"
+	"runtime"
+	"strings"
 	"sync"
 	"time"
 )
@@ -31,37 +35,85 @@ const (
 	levelError
 )
 
+const (
+	timeFormat = "2006-01-02 15:04:05"
+)
+
 var (
 	selectedLogLevel = levelInfo
-	staticData       = ""
+	staticData       = "| "
 
 	logStaticDataSet sync.Once
 )
 
-func Info(v ...any) {
+func newLoggerWithCaller(lvl string, noCallerAttached bool) *log.Logger {
+	callStackSkip := 3
+	withCaller := ""
+	if !noCallerAttached {
+		if _, caller, line, ok := runtime.Caller(callStackSkip); ok {
+			withCaller = fmt.Sprintf("caller:%s:%d | ", filepath.Base(caller), line)
+		}
+	}
+	return log.New(os.Stdout, "["+time.Now().UTC().Format(timeFormat)+"] "+lvl+" "+staticData+withCaller, flags)
+}
+
+type T interface {
+	Info(v ...any)
+	Warn(v ...any)
+	Error(v ...any)
+	Debug(v ...any)
+}
+
+type internalLog struct {
+	noCallerAttached bool
+}
+
+func (i internalLog) Info(v ...any) {
 	if selectedLogLevel <= levelInfo {
-		log.New(os.Stdout, "INF: "+time.Now().UTC().String()+" | "+staticData, flags).Println(v...)
+		newLoggerWithCaller("INF", i.noCallerAttached).Println(v...)
 	}
 }
 
-func Warn(v ...any) {
+func (i internalLog) Warn(v ...any) {
 	if selectedLogLevel <= levelWarn {
-		log.New(os.Stdout, "WRN: "+time.Now().UTC().String()+" | "+staticData, flags).Println(v...)
+		newLoggerWithCaller("WRN", i.noCallerAttached).Println(v...)
 	}
 }
 
-func Error(v ...any) {
+func (i internalLog) Error(v ...any) {
 	if selectedLogLevel <= levelError {
-		log.New(os.Stdout, "ERR: "+time.Now().UTC().String()+" | "+staticData, flags).Println(v...)
+		newLoggerWithCaller("ERR", i.noCallerAttached).Println(v...)
 	}
 }
 
-func Debug(v ...any) {
+func (i internalLog) Debug(v ...any) {
 	if selectedLogLevel <= levelDebug {
-		log.New(os.Stdout, "DBG: "+time.Now().UTC().String()+" | "+staticData, flags).Println(v...)
+		newLoggerWithCaller("DBG", i.noCallerAttached).Println(v...)
 	}
 }
 
+func WithNoCaller() T {
+	return &internalLog{
+		noCallerAttached: true,
+	}
+}
+
+func Info(v ...any) {
+	internalLog{}.Info(v...)
+}
+
+func Warn(v ...any) {
+	internalLog{}.Warn(v...)
+}
+
+func Error(v ...any) {
+	internalLog{}.Error(v...)
+}
+
+func Debug(v ...any) {
+	internalLog{}.Debug(v...)
+}
+
 func SetLogLevel(lvl string) {
 	switch Level(lvl) {
 	case LevelInfo:
@@ -75,11 +127,32 @@ func SetLogLevel(lvl string) {
 	}
 }
 
-func SetStaticData(data string) {
-	if data == "" {
-		return
+type Setter interface {
+	Add(key, value string) Setter
+	Set()
+}
+
+type set struct {
+	setBuffer *strings.Builder
+}
+
+func GetStaticDataSetter() Setter {
+	return &set{
+		setBuffer: &strings.Builder{},
 	}
+}
+
+func (s *set) Add(key, value string) Setter {
+	s.setBuffer.WriteString(fmt.Sprintf("%s:%s | ", key, value))
+	return s
+}
+
+func (s *set) Set() {
 	logStaticDataSet.Do(func() {
-		staticData = data + " | "
+		data := s.setBuffer.String()
+		if data == "" {
+			return
+		}
+		staticData += data
 	})
 }

middleware/panic_recovery.go

@@ -12,9 +12,9 @@ func RecoverPanic(next http.Handler) http.Handler {
 		defer func() {
 			if err := recover(); err != nil {
 				response.ToJson(w, http.StatusInternalServerError, "Oops! Something went wrong.", nil)
-				log.Warn("Panic occurred:", err)
+				log.WithNoCaller().Warn("Panic occurred:", err)
 				if e, ok := err.(error); ok {
-					log.Warn("Panic occurred:", e.Error())
+					log.WithNoCaller().Warn("Panic occurred:", e.Error())
 				}
 			}
 		}()

middleware/request_hijacker.go

@@ -5,6 +5,8 @@ import (
 	"net/http"
 	"time"
 
+	"github.com/google/uuid"
+
 	"github.com/PereRohit/util/constant"
 	"github.com/PereRohit/util/log"
 )
@@ -27,6 +29,11 @@ func (w *respWriterWithStatus) Write(d []byte) (int, error) {
 
 func RequestHijacker(next http.Handler) http.Handler {
 	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		reqId := r.Header.Get(constant.RequestIdHeader)
+		if reqId == "" {
+			reqId = uuid.NewString()
+			r.Header.Set(constant.RequestIdHeader, reqId)
+		}
 		rT := *r
 		hijackedWriter := &respWriterWithStatus{-1, "", w}
 
@@ -35,6 +42,7 @@ func RequestHijacker(next http.Handler) http.Handler {
 		w.Header().Set("user-agent", constant.UserAgentSvc)
 		end := time.Now().Sub(start)
 
-		log.Info(fmt.Sprintf("%20s | %5s | %20s | %d | %10s | %s", rT.RemoteAddr, rT.Method, rT.URL.String(), hijackedWriter.status, end.String(), hijackedWriter.response))
+		log.WithNoCaller().Info(fmt.Sprintf("%20s | %-6s | %-25s | %d | %10s | %s:%s | %s",
+			rT.RemoteAddr, rT.Method, rT.URL.String(), hijackedWriter.status, end.String(), constant.RequestIdHeader, reqId, hijackedWriter.response))
 	})
 }

server/server.go

@@ -38,14 +38,14 @@ func Run(r http.Handler, svrConfig config.ServerConfig) {
 
 	// set log data
 	log.SetLogLevel(svrConfig.LogLevel)
-	logStaticData := ""
+	logSetter := log.GetStaticDataSetter()
 	if svrConfig.Name != "" {
-		logStaticData += "name: " + svrConfig.Name
+		logSetter.Add("service", svrConfig.Name)
 	}
 	if svrConfig.Version != "" {
-		logStaticData += " version: " + svrConfig.Version
+		logSetter.Add("version", svrConfig.Version)
 	}
-	log.SetStaticData(logStaticData)
+	logSetter.Set()
 
 	s := &http.Server{
 		Addr:    fmt.Sprintf("%s:%s", host, port),
@@ -60,18 +60,18 @@ func Run(r http.Handler, svrConfig config.ServerConfig) {
 		// wait for termination signal
 		<-sc
 
-		log.Info("Closing Server")
+		log.WithNoCaller().Info("Closing Server")
 		err := s.Shutdown(context.Background())
 		if err != nil {
 			panic(err)
 		}
-		log.Info("Server Closed!!")
+		log.WithNoCaller().Info("Server Closed!!")
 	}()
 
 	srvStop.Add(1)
-	log.Info(fmt.Sprintf("Starting server(%s)", s.Addr))
+	log.WithNoCaller().Info(fmt.Sprintf("Starting server(%s)", s.Addr))
 	err := s.ListenAndServe()
 	if err != nil && !errors.Is(err, http.ErrServerClosed) {
-		log.Error("Server error::", err.Error())
+		log.WithNoCaller().Error("Server error::", err.Error())
 	}
 }