fix flushing buffer, add requestId to context

src/logger/bufio_wrapper.go

@@ -5,21 +5,25 @@ import (
 	"sync"
 )
 
-type BufioWrapper struct {
+type bufioWrapper struct {
 	*bufio.Writer
 	m *sync.RWMutex
 }
 
-func (b *BufioWrapper) Write(p []byte) (nn int, err error) {
+func (b *bufioWrapper) Write(p []byte) (nn int, err error) {
 	b.m.RLock()
 	defer b.m.RUnlock()
 
 	return b.Writer.Write(p)
 }
 
-func (b *BufioWrapper) Flush() error {
+func (b *bufioWrapper) Flush() error {
 	b.m.Lock()
 	defer b.m.Unlock()
 
 	return b.Writer.Flush()
 }
+
+func (b *bufioWrapper) Close() error {
+	return b.Flush()
+}

src/logger/logger.go

@@ -1,12 +1,14 @@
 package logger
 
 import (
-	"backend/src/request_context"
 	"context"
 
+	"github.com/gin-gonic/gin"
 	"github.com/rs/zerolog"
 )
 
+const RequestIdKey = "logger_request_id"
+
 type Logger interface {
 	Log() Event
 	Warning() Event
@@ -14,11 +16,14 @@ type Logger interface {
 	Fatal() Event
 
 	Printf(format string, v ...any)
+
+	WithContext(ctx context.Context) Logger
+	WithPrefix(prefix string) Logger
 }
 
 type logger struct {
 	prefix     string
-	requestCtx request_context.RequestContext
+	requestId  string
 	zeroLogger *zerolog.Logger
 }
 
@@ -45,33 +50,38 @@ func (l logger) Printf(format string, v ...any) {
 func (l logger) wrapEvent(zerologEvent *zerolog.Event) Event {
 	var e Event = event{zerologEvent}
 
-	if l.requestCtx != nil {
+	if l.requestId != "" {
-		e = e.Str("requestId", l.requestCtx.RequestId())
+		e = e.Str("requestId", l.requestId)
-		e = e.Str("userId", l.requestCtx.UserId())
+	}
-		if l.prefix != "" {
+	if l.prefix != "" {
-			e = e.Str("prefix", l.prefix)
+		e = e.Str("prefix", l.prefix)
-		}
 	}
 
 	return e
 }
 
 func (l logger) WithContext(ctx context.Context) Logger {
-	if rctx, ok := ctx.(request_context.RequestContext); ok {
+	requestIdVal := ctx.Value(RequestIdKey)
-		return logger{
+	requestId, ok := requestIdVal.(string)
-			prefix:     l.prefix,
+	if !ok || requestId == "" {
-			requestCtx: rctx,
+		return l
-			zeroLogger: l.zeroLogger,
-		}
 	}
 
-	return l
+	return logger{
+		prefix:     l.prefix,
+		requestId:  requestId,
+		zeroLogger: l.zeroLogger,
+	}
 }
 
 func (l logger) WithPrefix(prefix string) Logger {
 	return logger{
 		prefix:     prefix,
-		requestCtx: l.requestCtx,
+		requestId:  l.requestId,
 		zeroLogger: l.zeroLogger,
 	}
 }
+
+func SetCtxRequestId(ginCtx *gin.Context, requestId string) {
+	ginCtx.Set(RequestIdKey, requestId)
+}

src/logger/new.go

@@ -42,8 +42,8 @@ func New(opts NewLoggerOpts) (Logger, error) {
 		level = zerolog.DebugLevel
 	}
 
-	writer := bufio.NewWriterSize(io.MultiWriter(writers...), 32*1024)
+	writer := bufio.NewWriterSize(io.MultiWriter(writers...), 8*1024)
-	wrapper := &BufioWrapper{writer, &sync.RWMutex{}}
+	wrapper := &bufioWrapper{writer, &sync.RWMutex{}}
 	go func() {
 		tmr := time.NewTicker(500 * time.Millisecond)
 		defer tmr.Stop()
@@ -53,6 +53,7 @@ func New(opts NewLoggerOpts) (Logger, error) {
 
 			select {
 			case <-context.Background().Done():
+				wrapper.Flush()
 				return
 			case <-tmr.C:
 			}

src/request_context/ctx.go

@@ -1,59 +0,0 @@
-package request_context
-
-import (
-	"context"
-	"time"
-)
-
-type RequestContext interface {
-	context.Context
-
-	RequestId() string
-	UserId() string
-}
-
-type Opts struct {
-	RequestId string
-	UserId    string
-}
-
-func New(opts Opts) RequestContext {
-	return reqCtx{
-		requestId: opts.RequestId,
-		userId:    opts.UserId,
-	}
-}
-
-type reqCtx struct {
-	ctx       context.Context
-	requestId string
-	userId    string
-}
-
-func (r reqCtx) Deadline() (deadline time.Time, ok bool) {
-	return r.ctx.Deadline()
-}
-
-func (r reqCtx) Done() <-chan struct{} {
-	return r.ctx.Done()
-}
-
-func (r reqCtx) Err() error {
-	return r.ctx.Err()
-}
-
-func (r reqCtx) Value(key any) any {
-	return r.ctx.Value(key)
-}
-
-func (r reqCtx) String() string {
-	return r.ctx.Err().Error()
-}
-
-func (r reqCtx) RequestId() string {
-	return r.requestId
-}
-
-func (r reqCtx) UserId() string {
-	return r.userId
-}

src/server/handlers/long_pooling_handler.go

@@ -2,12 +2,13 @@ package handlers
 
 import (
 	"backend/src/client_notifier"
+	"backend/src/logger"
 	"backend/src/server/utils"
 
 	"github.com/gin-gonic/gin"
 )
 
-func NewLongPoolingHandler(notifier client_notifier.ClientNotifier) gin.HandlerFunc {
+func NewLongPoolingHandler(logger logger.Logger, notifier client_notifier.ClientNotifier) gin.HandlerFunc {
 	return func(c *gin.Context) {
 		user := utils.GetUserFromRequest(c)
 		if user == nil {

src/server/handlers/user_create_handler.go

@@ -2,6 +2,7 @@ package handlers
 
 import (
 	"backend/src/core/services"
+	"backend/src/logger"
 	"encoding/json"
 
 	"github.com/gin-gonic/gin"
@@ -19,38 +20,54 @@ type createUserOutput struct {
 	Name  string `json:"name"`
 }
 
-func NewUserCreateHandler(userService services.UserService) gin.HandlerFunc {
+func NewUserCreateHandler(logger logger.Logger, userService services.UserService) gin.HandlerFunc {
-	return func(ctx *gin.Context) {
+	return func(c *gin.Context) {
+		ctxLogger := logger.WithContext(c)
+
 		params := createUserInput{}
-		if err := ctx.ShouldBindJSON(&params); err != nil {
+		if err := c.ShouldBindJSON(&params); err != nil {
-			ctx.AbortWithError(400, err)
+			ctxLogger.Error().Err(err).Msg("bad input body model")
+			c.Data(400, "plain/text", []byte(err.Error()))
 			return
 		}
 
-		dto, err := userService.CreateUser(ctx, services.UserCreateParams{
+		dto, err := userService.CreateUser(
-			Email:    params.Email,
+			c,
-			Password: params.Password,
+			services.UserCreateParams{
-			Name:     params.Name,
+				Email:    params.Email,
-		})
+				Password: params.Password,
-		if err == services.ErrUserExists || err == services.ErrUserBadPassword {
+				Name:     params.Name,
-			ctx.Data(400, "plain/text", []byte(err.Error()))
+			},
+		)
+		if err == services.ErrUserExists {
+			ctxLogger.Error().Err(err).Msg("user already exists")
+			c.Data(400, "plain/text", []byte(err.Error()))
+			return
+		}
+		if err == services.ErrUserBadPassword {
+			ctxLogger.Error().Err(err).Msg("password does not satisfy requirements")
+			c.Data(400, "plain/text", []byte(err.Error()))
 			return
 		}
 		if err != nil {
-			ctx.Data(500, "plain/text", []byte(err.Error()))
+			ctxLogger.Error().Err(err).Msg("create user error")
+			c.Data(500, "plain/text", []byte(err.Error()))
 			return
 		}
 
-		resultBody, err := json.Marshal(createUserOutput{
+		resultBody, err := json.Marshal(
-			Id:    dto.Id,
+			createUserOutput{
-			Email: dto.Email,
+				Id:    dto.Id,
-			Name:  dto.Name,
+				Email: dto.Email,
-		})
+				Name:  dto.Name,
+			},
+		)
 		if err != nil {
-			ctx.AbortWithError(500, err)
+			ctxLogger.Error().Err(err).Msg("marshal user model error")
+			c.Data(500, "plain/text", []byte(err.Error()))
 			return
 		}
 
-		ctx.Data(200, "application/json", resultBody)
+		c.Data(200, "application/json", resultBody)
 	}
 }

src/server/handlers/user_login_handler.go

@@ -2,6 +2,7 @@ package handlers
 
 import (
 	"backend/src/core/services"
+	"backend/src/logger"
 	"encoding/json"
 
 	"github.com/gin-gonic/gin"
@@ -16,21 +17,31 @@ type loginUserOutput struct {
 	Token string `json:"token"`
 }
 
-func NewUserLoginHandler(userService services.UserService) gin.HandlerFunc {
+func NewUserLoginHandler(logger logger.Logger, userService services.UserService) gin.HandlerFunc {
-	return func(ctx *gin.Context) {
+	return func(c *gin.Context) {
+		ctxLogger := logger.WithContext(c).WithPrefix("NewUserLoginHandler")
+
 		params := loginUserInput{}
-		if err := ctx.ShouldBindJSON(&params); err != nil {
+		if err := c.ShouldBindJSON(&params); err != nil {
-			ctx.AbortWithError(400, err)
+			ctxLogger.Error().Err(err).Msg("bad input body model")
+			c.AbortWithError(400, err)
 			return
 		}
 
-		token, err := userService.AuthenticateUser(ctx, params.Login, params.Password)
+		token, err := userService.AuthenticateUser(c, params.Login, params.Password)
-		if err == services.ErrUserNotExists || err == services.ErrUserWrongPassword {
+		if err == services.ErrUserNotExists {
-			ctx.AbortWithError(400, err)
+			ctxLogger.Error().Err(err).Msg("user does not exist")
+			c.AbortWithError(400, err)
+			return
+		}
+		if err == services.ErrUserWrongPassword {
+			ctxLogger.Error().Err(err).Msg("wrong password")
+			c.AbortWithError(400, err)
 			return
 		}
 		if err != nil {
-			ctx.AbortWithError(500, err)
+			ctxLogger.Error().Err(err).Msg("AuthenticateUser internal error")
+			c.AbortWithError(500, err)
 			return
 		}
 
@@ -38,10 +49,11 @@ func NewUserLoginHandler(userService services.UserService) gin.HandlerFunc {
 			Token: token,
 		})
 		if err != nil {
-			ctx.AbortWithError(500, err)
+			ctxLogger.Error().Err(err).Msg("marshal json internal error")
+			c.AbortWithError(500, err)
 			return
 		}
 
-		ctx.Data(200, "application/json", resultBody)
+		c.Data(200, "application/json", resultBody)
 	}
 }

src/server/middleware/request_log.go

@@ -1,20 +1,22 @@
 package middleware
 
 import (
-	"backend/src/logger"
+	log "backend/src/logger"
 	"time"
 
 	"github.com/gin-gonic/gin"
 	"github.com/google/uuid"
 )
 
-func NewRequestLogMiddleware(logger logger.Logger) gin.HandlerFunc {
+func NewRequestLogMiddleware(logger log.Logger) gin.HandlerFunc {
 	return func(c *gin.Context) {
 		requestId := c.GetHeader("X-Request-Id")
 		if requestId == "" {
 			requestId = uuid.New().String()
 		}
 
+		log.SetCtxRequestId(c, requestId)
+
 		path := c.Request.URL.Path
 		if c.Request.URL.RawQuery != "" {
 			path = path + "?" + c.Request.URL.RawQuery
@@ -28,9 +30,10 @@ func NewRequestLogMiddleware(logger logger.Logger) gin.HandlerFunc {
 		statusCode := c.Writer.Status()
 		clientIP := c.ClientIP()
 
-		e := logger.Log()
+		ctxLogger := logger.WithContext(c)
-		e.Str("id", requestId)
+
+		e := ctxLogger.Log()
 		e.Str("ip", clientIP)
-		e.Msgf("[REQUEST] %s %s %d %v", method, path, statusCode, latency)
+		e.Msgf("Request %s %s %d %v", method, path, statusCode, latency)
 	}
 }

src/server/server.go

@@ -32,20 +32,21 @@ func New(opts NewServerOpts) *Server {
 	}
 
 	r := gin.New()
+	r.Static("/webapp", "./webapp")
+	r.GET("/health", handlers.NewDummyHandler())
+
 	r.Use(middleware.NewRequestLogMiddleware(opts.Logger))
 	r.Use(middleware.NewRecoveryMiddleware(opts.Logger, opts.DebugMode))
 
-	r.Static("/webapp", "./webapp")
+	r.GET("/pooling", handlers.NewLongPoolingHandler(opts.Logger, opts.Notifier))
-
-	r.GET("/pooling", handlers.NewLongPoolingHandler(opts.Notifier))
 
 	linkGroup := r.Group("/s")
 	linkGroup.POST("/new", handlers.NewShortlinkCreateHandler(opts.ShortlinkService))
 	linkGroup.GET("/:linkId", handlers.NewShortlinkResolveHandler(opts.ShortlinkService))
 
 	userGroup := r.Group("/user")
-	userGroup.POST("/create", handlers.NewUserCreateHandler(opts.UserService))
+	userGroup.POST("/create", handlers.NewUserCreateHandler(opts.Logger, opts.UserService))
-	userGroup.POST("/login", handlers.NewUserLoginHandler(opts.UserService))
+	userGroup.POST("/login", handlers.NewUserLoginHandler(opts.Logger, opts.UserService))
 
 	dummyGroup := r.Group("/dummy")
 	{