From 4d37323e8b0708f91d12572f842eb6682e942365 Mon Sep 17 00:00:00 2001 From: Sergey Chubaryan Date: Sun, 28 Jul 2024 00:20:17 +0300 Subject: [PATCH] improve loging, add request log middleware --- config/config.go | 6 +++++ config_example/config.yaml | 3 ++- go.mod | 1 + go.sum | 2 ++ log.txt | 46 +++++++++++++++++++++++++++++++++++ logger/event.go | 7 ++++++ logger/new.go | 2 +- main.go | 12 +++++++-- src/middleware/request_log.go | 36 +++++++++++++++++++++++++++ 9 files changed, 111 insertions(+), 4 deletions(-) create mode 100755 log.txt create mode 100644 src/middleware/request_log.go diff --git a/config/config.go b/config/config.go index adba7e8..925fed2 100644 --- a/config/config.go +++ b/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 +} diff --git a/config_example/config.yaml b/config_example/config.yaml index eb20078..c9b7276 100644 --- a/config_example/config.yaml +++ b/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" \ No newline at end of file +jwt_signing_key: "./config_example/jwt_signing_key" +log_file: "./log.txt" \ No newline at end of file diff --git a/go.mod b/go.mod index 7fd583a..ef9cc86 100644 --- a/go.mod +++ b/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 diff --git a/go.sum b/go.sum index aafa458..8826889 100644 --- a/go.sum +++ b/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= diff --git a/log.txt b/log.txt new file mode 100755 index 0000000..90ff45a --- /dev/null +++ b/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"} diff --git a/logger/event.go b/logger/event.go index 0422b8b..07ce2e2 100644 --- a/logger/event.go +++ b/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 diff --git a/logger/new.go b/logger/new.go index 8cda8d7..7412a12 100644 --- a/logger/new.go +++ b/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 diff --git a/main.go b/main.go index 02765b0..ee1c9c4 100644 --- a/main.go +++ b/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") + } } diff --git a/src/middleware/request_log.go b/src/middleware/request_log.go new file mode 100644 index 0000000..5f79b58 --- /dev/null +++ b/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) + } +}