improve loging, add request log middleware

config/config.go

@@ -4,12 +4,14 @@ type IConfig interface {
 	GetPort() uint16
 	GetPostgresUrl() string
 	GetJwtSigningKey() string
+	GetLogFile() string
 }
 
 type Config struct {
 	Port          uint16 `yaml:"port"`
 	PostgresUrl   string `yaml:"postgres_url"`
 	JwtSigningKey string `yaml:"jwt_signing_key" validate:"file"`
+	LogFile       string `yaml:"log_file"`
 }
 
 func (c *Config) GetPort() uint16 {
@@ -23,3 +25,7 @@ func (c *Config) GetPostgresUrl() string {
 func (c *Config) GetJwtSigningKey() string {
 	return c.JwtSigningKey
 }
+
+func (c *Config) GetLogFile() string {
+	return c.LogFile
+}

config_example/config.yaml

@@ -1,3 +1,4 @@
 port: 8080
 postgres_url: "postgres://postgres:postgres@localhost:5432/postgres"
-jwt_signing_key: "./config_example/jwt_signing_key"
+jwt_signing_key: "./config_example/jwt_signing_key"
+log_file: "./log.txt"

go.mod

@@ -7,6 +7,7 @@ require (
 	github.com/gin-gonic/gin v1.10.0
 	github.com/go-playground/validator/v10 v10.22.0
 	github.com/golang-jwt/jwt/v5 v5.2.1
+	github.com/google/uuid v1.6.0
 	github.com/jackc/pgx v3.6.2+incompatible
 	github.com/rs/zerolog v1.33.0
 	github.com/stretchr/testify v1.9.0

go.sum

@@ -39,6 +39,8 @@ github.com/golang-jwt/jwt/v5 v5.2.1/go.mod h1:pqrtFR0X4osieyHYxtmOUWsAWrfe1Q5UVI
 github.com/google/go-cmp v0.5.5 h1:Khx7svrCpmxxtHBq5j2mp/xVjsi8hQMfNLvJFAlrGgU=
 github.com/google/go-cmp v0.5.5/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE=
 github.com/google/gofuzz v1.0.0/go.mod h1:dBl0BpW6vV/+mYPU4Po3pmUjxk6FQPldtuIdl/M65Eg=
+github.com/google/uuid v1.6.0 h1:NIvaJDMOsjHA8n1jAhLSgzrAzy1Hgr+hNrb57e+94F0=
+github.com/google/uuid v1.6.0/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo=
 github.com/jackc/fake v0.0.0-20150926172116-812a484cc733 h1:vr3AYkKovP8uR8AvSGGUK1IDqRa5lAAvEkZG1LKaCRc=
 github.com/jackc/fake v0.0.0-20150926172116-812a484cc733/go.mod h1:WrMFNQdiFJ80sQsxDoMokWK1W5TQtxBFNpzWTD84ibQ=
 github.com/jackc/pgx v3.6.2+incompatible h1:2zP5OD7kiyR3xzRYMhOcXVvkDZsImVXfj+yIyTQf3/o=

log.txt

@@ -0,0 +1,46 @@
+{"id":"7d84e373-bd2d-4a56-b43e-4ed00eccaf8d","ip":"::1","time":"2024-07-28T00:05:01+03:00","message":"[REQUEST] GET /dummy/ 403 1.071044ms"}
+{"id":"a62f438c-0bd8-409f-a140-cbe2211197ef","ip":"::1","time":"2024-07-28T00:07:03+03:00","message":"[REQUEST] GET /dummy/ 403 1.150272ms"}
+{"id":"601e6ccb-0c94-4584-b314-f737afb45362","ip":"::1","time":"2024-07-28T00:07:19+03:00","message":"[REQUEST] GET /dummy/ 403 434.046µs"}
+{"id":"864b8c26-3fef-4306-b80a-ee0dea7d129c","ip":"::1","time":"2024-07-28T00:08:05+03:00","message":"[REQUEST] GET /dummy/ 403 830.822µs"}
+{"id":"1cd49608-9e24-47ae-9f4a-519cfc5ad8c2","ip":"::1","time":"2024-07-28T00:08:21+03:00","message":"[REQUEST] GET /dummy/ 403 904.345µs"}
+{"id":"efa2a2c5-e0ee-4ffe-97a7-8b2b8f780f96","ip":"::1","time":"2024-07-28T00:08:46+03:00","message":"[REQUEST] GET /dummy/ 403 974.096µs"}
+{"id":"ec876c3d-ad92-4d69-860c-88a4a50bb7f7","ip":"::1","time":"2024-07-28T00:09:23+03:00","message":"[REQUEST] GET /dummy/ 403     366.314µs"}
+{"id":"0a68f2fa-a21c-45ea-b2d0-d67b86298bf8","ip":"::1","time":"2024-07-28T00:09:44+03:00","message":"[REQUEST] GET /dummy/ 403 779.611µs"}
+{"id":"71b0f35f-8e13-43eb-bc21-de68e30d2e2a","ip":"::1","time":"2024-07-28T00:09:56+03:00","message":"[REQUEST] GET /dummy/ 403 737.861µs"}
+{"id":"298b9d65-c6a3-4beb-a5ec-a93b2c3445b5","ip":"::1","time":"2024-07-28T00:09:56+03:00","message":"[REQUEST] GET /dummy/ 403 592.001µs"}
+{"id":"18c1bfa7-a0e1-45ed-b7b9-335ecd05e5ce","ip":"::1","time":"2024-07-28T00:09:56+03:00","message":"[REQUEST] GET /dummy/ 403 382.473µs"}
+{"id":"18b63e20-4987-441d-b743-9b39d04ac613","ip":"::1","time":"2024-07-28T00:09:56+03:00","message":"[REQUEST] GET /dummy/ 403 697.475µs"}
+{"id":"8c481e15-3a1f-43ee-b325-72197acd210a","ip":"::1","time":"2024-07-28T00:09:57+03:00","message":"[REQUEST] GET /dummy/ 403 391.098µs"}
+{"id":"62a3a9b8-289f-49c4-a2e4-0db5e7252080","ip":"::1","time":"2024-07-28T00:09:57+03:00","message":"[REQUEST] GET /dummy/ 403 758.265µs"}
+{"id":"4d9ae6db-e732-432e-a959-f4517ef08c05","ip":"::1","time":"2024-07-28T00:09:57+03:00","message":"[REQUEST] GET /dummy/ 403 849.04µs"}
+{"id":"771a14dd-53c3-417b-ad28-1c6dbaac66a4","ip":"::1","time":"2024-07-28T00:09:57+03:00","message":"[REQUEST] GET /dummy/ 403 441.744µs"}
+{"id":"f3154318-0473-4138-95e6-d1bd73762b44","ip":"::1","time":"2024-07-28T00:09:57+03:00","message":"[REQUEST] GET /dummy/ 403 328.069µs"}
+{"id":"de023cf5-de13-4eff-b344-080c5d4689a5","ip":"::1","time":"2024-07-28T00:09:57+03:00","message":"[REQUEST] GET /dummy/ 403 407.784µs"}
+{"id":"6976853e-51ce-4f2b-bebe-73e018dabec8","ip":"::1","time":"2024-07-28T00:09:57+03:00","message":"[REQUEST] GET /dummy/ 403 384.479µs"}
+{"id":"9298cb66-8cc9-43da-a970-f25ef0019c37","ip":"::1","time":"2024-07-28T00:09:58+03:00","message":"[REQUEST] GET /dummy/ 403 970.979µs"}
+{"id":"10078460-3a23-46e7-b987-bf388c0d8a23","ip":"::1","time":"2024-07-28T00:09:58+03:00","message":"[REQUEST] GET /dummy/ 403 665.252µs"}
+{"id":"6987fb98-6136-4856-99b4-e678a638a532","ip":"::1","time":"2024-07-28T00:09:58+03:00","message":"[REQUEST] GET /dummy/ 403 384.368µs"}
+{"id":"87a98b39-bb30-4946-8925-2969bdfec61e","ip":"::1","time":"2024-07-28T00:09:58+03:00","message":"[REQUEST] GET /dummy/ 403 343.223µs"}
+{"id":"983804bd-d6cb-4400-bf72-fba00d54d8b4","ip":"::1","time":"2024-07-28T00:09:58+03:00","message":"[REQUEST] GET /dummy/ 403 314.217µs"}
+{"time":"2024-07-28T00:10:51+03:00","message":"[REQUEST] GET /dummy/ 403 384.994µs"}
+{"time":"2024-07-28T00:10:51+03:00","message":"[REQUEST] GET /dummy/ 403 745.943µs"}
+{"time":"2024-07-28T00:10:51+03:00","message":"[REQUEST] GET /dummy/ 403 620.702µs"}
+{"time":"2024-07-28T00:10:51+03:00","message":"[REQUEST] GET /dummy/ 403 430.681µs"}
+{"time":"2024-07-28T00:10:51+03:00","message":"[REQUEST] GET /dummy/ 403 397.706µs"}
+{"time":"2024-07-28T00:10:52+03:00","message":"[REQUEST] GET /dummy/ 403 406.541µs"}
+{"time":"2024-07-28T00:10:52+03:00","message":"[REQUEST] GET /dummy/ 403 895.803µs"}
+{"time":"2024-07-28T00:10:52+03:00","message":"[REQUEST] GET /dummy/ 403 401.696µs"}
+{"time":"2024-07-28T00:10:53+03:00","message":"[REQUEST] GET /dummy/ 403 428.535µs"}
+{"time":"2024-07-28T00:10:53+03:00","message":"[REQUEST] GET /dummy/ 403 534.078µs"}
+{"time":"2024-07-28T00:10:53+03:00","message":"[REQUEST] GET /dummy/ 403 1.049712ms"}
+{"time":"2024-07-28T00:10:53+03:00","message":"[REQUEST] GET /dummy/ 403 752.935µs"}
+{"time":"2024-07-28T00:10:53+03:00","message":"[REQUEST] GET /dummy/ 403 960.666µs"}
+{"time":"2024-07-28T00:10:53+03:00","message":"[REQUEST] GET /dummy/ 403 683.653µs"}
+{"time":"2024-07-28T00:10:53+03:00","message":"[REQUEST] GET /dummy/ 403 354.155µs"}
+{"time":"2024-07-28T00:10:53+03:00","message":"[REQUEST] GET /dummy/ 403 641.79µs"}
+{"time":"2024-07-28T00:10:54+03:00","message":"[REQUEST] GET /dummy/ 403 535.8µs"}
+{"time":"2024-07-28T00:10:54+03:00","message":"[REQUEST] GET /dummy/ 403 861.573µs"}
+{"time":"2024-07-28T00:17:41+03:00","message":"initializing service..."}
+{"time":"2024-07-28T00:17:41+03:00","message":"server listening on :8080"}
+{"time":"2024-07-28T00:17:54+03:00","message":"initializing service..."}
+{"time":"2024-07-28T00:17:54+03:00","message":"server listening on :8080"}

logger/event.go

@@ -3,7 +3,9 @@ package logger
 import "github.com/rs/zerolog"
 
 type Event interface {
+	Str(key, val string) Event
 	Err(err error) Event
+
 	Msg(msg string)
 	Msgf(format string, v ...interface{})
 }
@@ -12,6 +14,11 @@ type event struct {
 	zerologEvent *zerolog.Event
 }
 
+func (e event) Str(key, val string) Event {
+	e.zerologEvent = e.zerologEvent.Str(key, val)
+	return e
+}
+
 func (e event) Err(err error) Event {
 	e.zerologEvent = e.zerologEvent.Err(err)
 	return e

logger/new.go

@@ -40,7 +40,7 @@ func New(opts NewLoggerOpts) (Logger, error) {
 
 	writer := io.MultiWriter(writers...)
 
-	l := zerolog.New(writer).Level(level)
+	l := zerolog.New(writer).Level(level).With().Timestamp().Logger()
 	return &logger{
 		zeroLogger: &l,
 	}, nil

main.go

@@ -38,6 +38,8 @@ func main() {
 		panic(err)
 	}
 
+	logger.Log().Msg("initializing service...")
+
 	conf, err := config.NewFromFile(args.GetConfigPath())
 	if err != nil {
 		logger.Fatal().Err(err).Msg("failed parsing config file")
@@ -90,7 +92,7 @@ func main() {
 	}
 
 	r := gin.New()
-	r.Use(gin.Logger())
+	r.Use(middleware.NewRequestLogMiddleware(logger))
 	r.Use(gin.Recovery())
 
 	userGroup := r.Group("/user")
@@ -101,5 +103,11 @@ func main() {
 	dummyGroup.Use(middleware.NewAuthMiddleware(userService))
 	dummyGroup.GET("/", handlers.NewDummyHandler())
 
-	r.Run(fmt.Sprintf(":%d", conf.GetPort()))
+	listenAddr := fmt.Sprintf(":%d", conf.GetPort())
+	logger.Log().Msgf("server listening on %s", listenAddr)
+
+	err = r.Run(listenAddr)
+	if err != nil {
+		logger.Fatal().Err(err).Msg("server stopped with error")
+	}
 }

src/middleware/request_log.go

@@ -0,0 +1,36 @@
+package middleware
+
+import (
+	"backend/logger"
+	"time"
+
+	"github.com/gin-gonic/gin"
+	"github.com/google/uuid"
+)
+
+func NewRequestLogMiddleware(logger logger.Logger) gin.HandlerFunc {
+	return func(c *gin.Context) {
+		requestId := c.GetHeader("X-Request-Id")
+		if requestId == "" {
+			requestId = uuid.New().String()
+		}
+
+		path := c.Request.URL.Path
+		if c.Request.URL.RawQuery != "" {
+			path = path + "?" + c.Request.URL.RawQuery
+		}
+
+		start := time.Now()
+		c.Next()
+		latency := time.Since(start)
+
+		method := c.Request.Method
+		statusCode := c.Writer.Status()
+		clientIP := c.ClientIP()
+
+		e := logger.Log()
+		e.Str("id", requestId)
+		e.Str("ip", clientIP)
+		e.Msgf("[REQUEST] %s %s %d %v", method, path, statusCode, latency)
+	}
+}