P1 #9: Структурированное логирование (slog) + Graceful shutdown

- Добавлен internal/log/log.go: инициализация slog (JSON в проде, text в деве), хелперы для контекста
- main.go: request logging middleware, graceful shutdown (30s таймаут), сигналы SIGINT/SIGTERM
- auth сервис: логирование регистрации, входа, refresh, отзыва сессий, очистки токенов
- HTTP сервер: ReadTimeout/WriteTimeout/IdleTimeout, корректное завершение

backend/cmd/api/main.go

@@ -2,8 +2,12 @@ package main
 
 import (
 	"context"
-	"log"
+	"log/slog"
 	"net/http"
+	"os"
+	"os/signal"
+	"syscall"
+	"time"
 
 	"github.com/go-chi/chi/v5"
 	chimiddleware "github.com/go-chi/chi/v5/middleware"
@@ -12,6 +16,7 @@ import (
 
 	"github.com/photoplaces/backend/internal/config"
 	"github.com/photoplaces/backend/internal/handlers"
+	"github.com/photoplaces/backend/internal/log"
 	"github.com/photoplaces/backend/internal/middleware"
 	"github.com/photoplaces/backend/internal/repository"
 	"github.com/photoplaces/backend/internal/services"
@@ -21,12 +26,26 @@ func main() {
 	cfg := config.Load()
 	ctx := context.Background()
 
+	// Инициализация структурированного логгера
+	logger := log.Init(cfg.AppEnv)
+	ctx = log.WithContext(ctx, logger)
+
+	logger.InfoContext(ctx, "starting application",
+		slog.String("env", cfg.AppEnv),
+		slog.String("port", cfg.ServerPort),
+	)
+
+	// Подключение к базе данных
 	pool, err := repository.NewPool(ctx, cfg.DatabaseURL)
 	if err != nil {
-		log.Fatalf("database connection: %v", err)
+		logger.ErrorContext(ctx, "database connection failed", log.WithError(err))
+		os.Exit(1)
 	}
 	defer pool.Close()
 
+	logger.InfoContext(ctx, "database connected")
+
+	// Репозитории
 	userRepo := repository.NewUserRepo(pool)
 	refreshTokenRepo := repository.NewRefreshTokenRepo(pool)
 	placeRepo := repository.NewPlaceRepo(pool)
@@ -36,9 +55,11 @@ func main() {
 	tagRepo := repository.NewTagRepo(pool)
 	featureRepo := repository.NewFeatureRepo(pool)
 
+	// Сервисы
 	authSvc := services.NewAuthService(userRepo, refreshTokenRepo, cfg.JWTSecret, cfg.JWTRefreshSecret)
 	placeSvc := services.NewPlaceService(placeRepo)
 
+	// Хендлеры
 	authHandler := handlers.NewAuthHandler(authSvc, cfg.AppEnv)
 	userHandler := handlers.NewUserHandler(userRepo)
 	placeHandler := handlers.NewPlaceHandler(placeSvc)
@@ -49,18 +70,23 @@ func main() {
 	wsHub := handlers.NewWSHub()
 	uploadHandler, err := handlers.NewUploadHandler(cfg.S3Endpoint, cfg.S3PublicEndpoint, cfg.S3AccessKey, cfg.S3SecretKey, cfg.S3Bucket, false)
 	if err != nil {
-		log.Fatalf("upload handler: %v", err)
+		logger.ErrorContext(ctx, "upload handler init failed", log.WithError(err))
+		os.Exit(1)
 	}
 
+	// Redis для rate limiting
 	redisOpts, err := redis.ParseURL(cfg.RedisURL)
 	if err != nil {
-		log.Fatalf("parse redis url: %v", err)
+		logger.ErrorContext(ctx, "parse redis url failed", log.WithError(err))
+		os.Exit(1)
 	}
 	redisClient := redis.NewClient(redisOpts)
 	defer redisClient.Close()
 
 	if err := redisClient.Ping(ctx).Err(); err != nil {
-		log.Printf("Warning: Redis connection failed, rate limiting disabled: %v", err)
+		logger.WarnContext(ctx, "redis connection failed, rate limiting disabled", log.WithError(err))
+	} else {
+		logger.InfoContext(ctx, "redis connected")
 	}
 
 	authLimiter, _ := middleware.RateLimitAuthEndpoints(redisClient)
@@ -68,9 +94,11 @@ func main() {
 	apiWriteLimiter, _ := middleware.RateLimitAPIWrite(redisClient)
 	adminLimiter, _ := middleware.RateLimitAdmin(redisClient)
 
+	// Роутер
 	r := chi.NewRouter()
 
-	r.Use(chimiddleware.Logger)
+	// Middleware для логирования запросов
+	r.Use(requestLoggerMiddleware(logger))
 	r.Use(chimiddleware.Recoverer)
 	r.Use(chimiddleware.RequestID)
 	r.Use(cors.Handler(cors.Options{
@@ -166,9 +194,67 @@ func main() {
 		})
 	})
 
-	port := cfg.ServerPort
-	log.Printf("Starting server on :%s", port)
-	if err := http.ListenAndServe(":"+port, r); err != nil {
-		log.Fatal(err)
+	// HTTP сервер с graceful shutdown
+	server := &http.Server{
+		Addr:         ":" + cfg.ServerPort,
+		Handler:      r,
+		ReadTimeout:  15 * time.Second,
+		WriteTimeout: 15 * time.Second,
+		IdleTimeout:  60 * time.Second,
+	}
+
+	// Запуск сервера в горутине
+	go func() {
+		logger.InfoContext(ctx, "starting http server", slog.String("addr", server.Addr))
+		if err := server.ListenAndServe(); err != nil && err != http.ErrServerClosed {
+			logger.ErrorContext(ctx, "http server error", log.WithError(err))
+			os.Exit(1)
+		}
+	}()
+
+	// Ожидание сигнала завершения
+	quit := make(chan os.Signal, 1)
+	signal.Notify(quit, syscall.SIGINT, syscall.SIGTERM)
+	<-quit
+
+	logger.InfoContext(ctx, "shutdown signal received, gracefully stopping...")
+
+	// Graceful shutdown с таймаутом
+	shutdownCtx, cancel := context.WithTimeout(context.Background(), 30*time.Second)
+	defer cancel()
+
+	if err := server.Shutdown(shutdownCtx); err != nil {
+		logger.ErrorContext(ctx, "server shutdown failed", log.WithError(err))
+		os.Exit(1)
 	}
+
+	logger.InfoContext(ctx, "server stopped gracefully")
 }
+
+// requestLoggerMiddleware логирует входящие HTTP запросы
+func requestLoggerMiddleware(logger *slog.Logger) func(http.Handler) http.Handler {
+	return func(next http.Handler) http.Handler {
+		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			start := time.Now()
+			ww := chimiddleware.NewWrapResponseWriter(w, r.ProtoMajor)
+
+			requestID := chimiddleware.GetReqID(r.Context())
+			ctx := log.WithContext(r.Context(), logger.With("request_id", requestID))
+
+			logger.InfoContext(ctx, "request started",
+				slog.String("method", r.Method),
+				slog.String("path", r.URL.Path),
+				slog.String("remote_addr", r.RemoteAddr),
+				slog.String("user_agent", r.UserAgent()),
+			)
+
+			next.ServeHTTP(ww, r.WithContext(ctx))
+
+			logger.InfoContext(ctx, "request completed",
+				slog.Int("status", ww.Status()),
+				slog.Int("bytes_written", ww.BytesWritten()),
+				slog.Duration("duration", time.Since(start)),
+			)
+		})
+	}
+}

backend/internal/log/log.go

@@ -0,0 +1,110 @@
+package log
+
+import (
+	"context"
+	"log/slog"
+	"os"
+	"runtime"
+)
+
+type ctxKey string
+
+const loggerKey ctxKey = "logger"
+
+var defaultLogger *slog.Logger
+
+func Init(env string) *slog.Logger {
+	var handler slog.Handler
+
+	if env == "production" {
+		handler = slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
+			Level:     slog.LevelInfo,
+			AddSource: true,
+			ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr {
+				if a.Key == slog.TimeKey {
+					return slog.Attr{Key: "timestamp", Value: a.Value}
+				}
+				if a.Key == slog.LevelKey {
+					return slog.Attr{Key: "level", Value: a.Value}
+				}
+				if a.Key == slog.MessageKey {
+					return slog.Attr{Key: "message", Value: a.Value}
+				}
+				return a
+			},
+		})
+	} else {
+		handler = slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{
+			Level:     slog.LevelDebug,
+			AddSource: true,
+		})
+	}
+
+	defaultLogger = slog.New(handler)
+	slog.SetDefault(defaultLogger)
+	return defaultLogger
+}
+
+func Default() *slog.Logger {
+	if defaultLogger == nil {
+		return slog.Default()
+	}
+	return defaultLogger
+}
+
+func FromContext(ctx context.Context) *slog.Logger {
+	if logger, ok := ctx.Value(loggerKey).(*slog.Logger); ok {
+		return logger
+	}
+	return Default()
+}
+
+func WithContext(ctx context.Context, logger *slog.Logger) context.Context {
+	return context.WithValue(ctx, loggerKey, logger)
+}
+
+func WithRequestID(ctx context.Context, requestID string) *slog.Logger {
+	return FromContext(ctx).With("request_id", requestID)
+}
+
+func WithUserID(ctx context.Context, userID string) *slog.Logger {
+	return FromContext(ctx).With("user_id", userID)
+}
+
+func WithError(err error) slog.Attr {
+	return slog.String("error", err.Error())
+}
+
+func WithFields(fields map[string]any) []slog.Attr {
+	attrs := make([]slog.Attr, 0, len(fields))
+	for k, v := range fields {
+		attrs = append(attrs, slog.Any(k, v))
+	}
+	return attrs
+}
+
+func LogError(ctx context.Context, msg string, err error, args ...any) {
+	logger := FromContext(ctx)
+	allArgs := append([]any{"error", err}, args...)
+	logger.ErrorContext(ctx, msg, allArgs...)
+}
+
+func LogWarn(ctx context.Context, msg string, args ...any) {
+	FromContext(ctx).WarnContext(ctx, msg, args...)
+}
+
+func LogInfo(ctx context.Context, msg string, args ...any) {
+	FromContext(ctx).InfoContext(ctx, msg, args...)
+}
+
+func LogDebug(ctx context.Context, msg string, args ...any) {
+	FromContext(ctx).DebugContext(ctx, msg, args...)
+}
+
+func callerInfo(skip int) slog.Attr {
+	_, file, line, ok := runtime.Caller(skip + 1)
+	if !ok {
+		return slog.String("caller", "unknown")
+	}
+	return slog.String("caller", file+":"+string(rune(line)))
+}

backend/internal/services/auth.go

@@ -9,6 +9,7 @@ import (
 	"time"
 
 	"github.com/golang-jwt/jwt/v5"
+	"github.com/photoplaces/backend/internal/log"
 	"github.com/photoplaces/backend/internal/models"
 	"github.com/photoplaces/backend/internal/repository"
 	"golang.org/x/crypto/bcrypt"
@@ -57,13 +58,17 @@ type RegisterInput struct {
 }
 
 func (s *AuthService) Register(ctx context.Context, input RegisterInput) (*AuthResult, string, error) {
+	logger := log.FromContext(ctx)
+
 	existing, _ := s.userRepo.GetByEmail(ctx, input.Email)
 	if existing != nil {
+		logger.WarnContext(ctx, "registration attempt with existing email", slog.String("email", input.Email))
 		return nil, "", ErrEmailExists
 	}
 
 	hash, err := bcrypt.GenerateFromPassword([]byte(input.Password), bcrypt.DefaultCost)
 	if err != nil {
+		logger.ErrorContext(ctx, "password hashing failed", log.WithError(err))
 		return nil, "", fmt.Errorf("hash password: %w", err)
 	}
 
@@ -75,9 +80,12 @@ func (s *AuthService) Register(ctx context.Context, input RegisterInput) (*AuthR
 	}
 
 	if err := s.userRepo.Create(ctx, user); err != nil {
+		logger.ErrorContext(ctx, "user creation failed", log.WithError(err), slog.String("email", input.Email))
 		return nil, "", fmt.Errorf("create user: %w", err)
 	}
 
+	logger.InfoContext(ctx, "user registered", slog.String("user_id", user.ID), slog.String("email", user.Email), slog.String("role", user.Role))
+
 	return s.generateTokens(ctx, user)
 }
 
@@ -87,22 +95,29 @@ type LoginInput struct {
 }
 
 func (s *AuthService) Login(ctx context.Context, input LoginInput) (*AuthResult, string, error) {
+	logger := log.FromContext(ctx)
+
 	user, err := s.userRepo.GetByEmail(ctx, input.Email)
 	if err != nil {
+		logger.ErrorContext(ctx, "user lookup failed", log.WithError(err), slog.String("email", input.Email))
 		return nil, "", fmt.Errorf("get user: %w", err)
 	}
 	if user == nil {
+		logger.WarnContext(ctx, "login attempt for non-existent user", slog.String("email", input.Email))
 		return nil, "", ErrInvalidCreds
 	}
 
 	if user.Status == "banned" {
+		logger.WarnContext(ctx, "login attempt for banned user", slog.String("user_id", user.ID))
 		return nil, "", ErrUserBanned
 	}
 
 	if err := bcrypt.CompareHashAndPassword([]byte(user.PasswordHash), []byte(input.Password)); err != nil {
+		logger.WarnContext(ctx, "invalid password attempt", slog.String("user_id", user.ID))
 		return nil, "", ErrInvalidCreds
 	}
 
+	logger.InfoContext(ctx, "user logged in", slog.String("user_id", user.ID), slog.String("role", user.Role))
 	return s.generateTokens(ctx, user)
 }
 
@@ -159,48 +174,65 @@ func (s *AuthService) ValidateAccessToken(tokenString string) (*TokenClaims, err
 }
 
 func (s *AuthService) RefreshSession(ctx context.Context, plainRefreshToken string) (*AuthResult, string, error) {
+	logger := log.FromContext(ctx)
+
 	storedToken, err := s.refreshTokenRepo.GetValid(ctx, plainRefreshToken)
 	if err != nil {
+		logger.ErrorContext(ctx, "refresh token lookup failed", log.WithError(err))
 		return nil, "", fmt.Errorf("lookup refresh token: %w", err)
 	}
 	if storedToken == nil {
+		logger.WarnContext(ctx, "refresh attempt with invalid/expired token")
 		return nil, "", ErrInvalidToken
 	}
 
 	user, err := s.userRepo.GetByID(ctx, storedToken.UserID)
 	if err != nil {
+		logger.ErrorContext(ctx, "user lookup failed during refresh", log.WithError(err), slog.String("user_id", storedToken.UserID))
 		return nil, "", fmt.Errorf("get user: %w", err)
 	}
 	if user == nil {
+		logger.WarnContext(ctx, "refresh attempt for deleted user", slog.String("user_id", storedToken.UserID))
 		return nil, "", ErrInvalidToken
 	}
 	if user.Status == "banned" {
+		logger.WarnContext(ctx, "refresh attempt for banned user", slog.String("user_id", user.ID))
 		return nil, "", ErrUserBanned
 	}
 
 	if err := s.refreshTokenRepo.Delete(ctx, storedToken.TokenHash); err != nil {
+		logger.ErrorContext(ctx, "failed to delete old refresh token", log.WithError(err))
 		return nil, "", fmt.Errorf("delete old refresh token: %w", err)
 	}
 
+	logger.InfoContext(ctx, "token refreshed", slog.String("user_id", user.ID))
 	return s.generateTokens(ctx, user)
 }
 
 func (s *AuthService) RevokeSession(ctx context.Context, plainRefreshToken string) error {
+	logger := log.FromContext(ctx)
+
 	storedToken, err := s.refreshTokenRepo.GetValid(ctx, plainRefreshToken)
 	if err != nil {
+		logger.ErrorContext(ctx, "revoke: refresh token lookup failed", log.WithError(err))
 		return fmt.Errorf("lookup refresh token: %w", err)
 	}
 	if storedToken == nil {
 		return nil
 	}
+	logger.InfoContext(ctx, "session revoked", slog.String("user_id", storedToken.UserID))
 	return s.refreshTokenRepo.Revoke(ctx, storedToken.TokenHash)
 }
 
 func (s *AuthService) RevokeAllSessions(ctx context.Context, userID string) error {
+	logger := log.FromContext(ctx)
+	logger.InfoContext(ctx, "revoking all sessions for user", slog.String("user_id", userID))
 	return s.refreshTokenRepo.RevokeAllForUser(ctx, userID)
 }
 
 func (s *AuthService) CleanupExpiredTokens(ctx context.Context) error {
+	logger := log.FromContext(ctx)
+	logger.InfoContext(ctx, "cleaning up expired refresh tokens")
 	return s.refreshTokenRepo.CleanupExpired(ctx)
 }