Add logging to app package

server/internal/app/config.go

@@ -58,37 +58,46 @@ func (c *Config) validate() error {
 
 // LoadConfig creates a new Config instance with values from environment variables
 func LoadConfig() (*Config, error) {
+	logging.Info("Loading configuration from environment variables")
 	config := DefaultConfig()
 
 	if env := os.Getenv("NOVAMD_ENV"); env != "" {
+		logging.Debug("Loading config for environment", "env", env)
 		config.IsDevelopment = env == "development"
 	}
 
 	if dbPath := os.Getenv("NOVAMD_DB_PATH"); dbPath != "" {
+		logging.Debug("Loading config for database path", "path", dbPath)
 		config.DBPath = dbPath
 	}
 
 	if workDir := os.Getenv("NOVAMD_WORKDIR"); workDir != "" {
+		logging.Debug("Loading config for work directory", "dir", workDir)
 		config.WorkDir = workDir
 	}
 
 	if staticPath := os.Getenv("NOVAMD_STATIC_PATH"); staticPath != "" {
+		logging.Debug("Loading config for static path", "path", staticPath)
 		config.StaticPath = staticPath
 	}
 
 	if port := os.Getenv("NOVAMD_PORT"); port != "" {
+		logging.Debug("Loading config for port", "port", port)
 		config.Port = port
 	}
 
 	if rootURL := os.Getenv("NOVAMD_ROOT_URL"); rootURL != "" {
+		logging.Debug("Loading config for root URL", "url", rootURL)
 		config.RootURL = rootURL
 	}
 
 	if domain := os.Getenv("NOVAMD_DOMAIN"); domain != "" {
+		logging.Debug("Loading config for domain", "domain", domain)
 		config.Domain = domain
 	}
 
 	if corsOrigins := os.Getenv("NOVAMD_CORS_ORIGINS"); corsOrigins != "" {
+		logging.Debug("Loading config for CORS origins", "origins", corsOrigins)
 		config.CORSOrigins = strings.Split(corsOrigins, ",")
 	}
 
@@ -97,15 +106,35 @@ func LoadConfig() (*Config, error) {
 	config.EncryptionKey = os.Getenv("NOVAMD_ENCRYPTION_KEY")
 	config.JWTSigningKey = os.Getenv("NOVAMD_JWT_SIGNING_KEY")
 
+	logging.Debug("Sensitive configuration loaded",
+		"adminEmailSet", config.AdminEmail != "",
+		"adminPasswordSet", config.AdminPassword != "",
+		"encryptionKeySet", config.EncryptionKey != "",
+		"jwtSigningKeySet", config.JWTSigningKey != "")
+
 	// Configure rate limiting
 	if reqStr := os.Getenv("NOVAMD_RATE_LIMIT_REQUESTS"); reqStr != "" {
-		if parsed, err := strconv.Atoi(reqStr); err == nil {
+		parsed, err := strconv.Atoi(reqStr)
+		if err != nil {
+			logging.Warn("Invalid rate limit requests value, using default",
+				"value", reqStr,
+				"default", config.RateLimitRequests,
+				"error", err)
+		} else {
+			logging.Debug("Loading config for rate limit requests", "requests", parsed)
 			config.RateLimitRequests = parsed
 		}
 	}
 
 	if windowStr := os.Getenv("NOVAMD_RATE_LIMIT_WINDOW"); windowStr != "" {
-		if parsed, err := time.ParseDuration(windowStr); err == nil {
+		parsed, err := time.ParseDuration(windowStr)
+		if err != nil {
+			logging.Warn("Invalid rate limit window value, using default",
+				"value", windowStr,
+				"default", config.RateLimitWindow,
+				"error", err)
+		} else {
+			logging.Debug("Loading config for rate limit window", "window", parsed)
 			config.RateLimitWindow = parsed
 		}
 	}
@@ -113,10 +142,13 @@ func LoadConfig() (*Config, error) {
 	// Configure log level, if isDevelopment is set, default to debug
 	if logLevel := os.Getenv("NOVAMD_LOG_LEVEL"); logLevel != "" {
 		parsed := logging.ParseLogLevel(logLevel)
+		logging.Debug("Loading config for log level", "level", parsed)
 		config.LogLevel = parsed
 	} else if config.IsDevelopment {
+		logging.Debug("Setting log level to debug for development")
 		config.LogLevel = logging.DEBUG
 	} else {
+		logging.Debug("Setting log level to info for production")
 		config.LogLevel = logging.INFO
 	}
 
@@ -125,5 +157,6 @@ func LoadConfig() (*Config, error) {
 		return nil, err
 	}
 
+	logging.Info("Configuration loaded successfully")
 	return config, nil
 }

server/internal/app/init.go

@@ -4,13 +4,13 @@ package app
 import (
 	"database/sql"
 	"fmt"
-	"log"
 	"time"
 
 	"golang.org/x/crypto/bcrypt"
 
 	"novamd/internal/auth"
 	"novamd/internal/db"
+	"novamd/internal/logging"
 	"novamd/internal/models"
 	"novamd/internal/secrets"
 	"novamd/internal/storage"
@@ -18,39 +18,53 @@ import (
 
 // initSecretsService initializes the secrets service
 func initSecretsService(cfg *Config) (secrets.Service, error) {
+	logging.Debug("Initializing secrets service")
 	secretsService, err := secrets.NewService(cfg.EncryptionKey)
 	if err != nil {
 		return nil, fmt.Errorf("failed to initialize secrets service: %w", err)
 	}
+	logging.Debug("Secrets service initialized")
 	return secretsService, nil
 }
 
 // initDatabase initializes and migrates the database
 func initDatabase(cfg *Config, secretsService secrets.Service) (db.Database, error) {
+	logging.Debug("Initializing database", "path", cfg.DBPath)
+
 	database, err := db.Init(cfg.DBPath, secretsService)
 	if err != nil {
 		return nil, fmt.Errorf("failed to initialize database: %w", err)
 	}
 
+	logging.Debug("Running database migrations")
 	if err := database.Migrate(); err != nil {
 		return nil, fmt.Errorf("failed to apply database migrations: %w", err)
 	}
 
+	logging.Debug("Database initialization complete")
 	return database, nil
 }
 
 // initAuth initializes JWT and session services
 func initAuth(cfg *Config, database db.Database) (auth.JWTManager, auth.SessionManager, auth.CookieManager, error) {
+	logging.Debug("Initializing authentication services")
+
 	// Get or generate JWT signing key
 	signingKey := cfg.JWTSigningKey
 	if signingKey == "" {
+		logging.Debug("No JWT signing key provided, generating new key")
 		var err error
 		signingKey, err = database.EnsureJWTSecret()
 		if err != nil {
 			return nil, nil, nil, fmt.Errorf("failed to ensure JWT secret: %w", err)
 		}
+		logging.Debug("JWT signing key generated")
 	}
 
+	logging.Debug("Initializing JWT service",
+		"accessTokenExpiry", "15m",
+		"refreshTokenExpiry", "168h")
+
 	// Initialize JWT service
 	jwtManager, err := auth.NewJWTService(auth.JWTConfig{
 		SigningKey:         signingKey,
@@ -62,36 +76,45 @@ func initAuth(cfg *Config, database db.Database) (auth.JWTManager, auth.SessionM
 	}
 
 	// Initialize session service
+	logging.Debug("Initializing session service")
 	sessionManager := auth.NewSessionService(database, jwtManager)
 
-	// Cookie service
+	// Initialize cookie service
+	logging.Debug("Initializing cookie service",
+		"isDevelopment", cfg.IsDevelopment,
+		"domain", cfg.Domain)
 	cookieService := auth.NewCookieService(cfg.IsDevelopment, cfg.Domain)
 
+	logging.Debug("Authentication services initialized")
 	return jwtManager, sessionManager, cookieService, nil
 }
 
 // setupAdminUser creates the admin user if it doesn't exist
 func setupAdminUser(database db.Database, storageManager storage.Manager, cfg *Config) error {
-	adminEmail := cfg.AdminEmail
-	adminPassword := cfg.AdminPassword
+	logging.Debug("Checking for existing admin user", "email", cfg.AdminEmail)
 
 	// Check if admin user exists
-	adminUser, err := database.GetUserByEmail(adminEmail)
-	if adminUser != nil {
-		return nil // Admin user already exists
-	} else if err != sql.ErrNoRows {
-		return err
+	adminUser, err := database.GetUserByEmail(cfg.AdminEmail)
+	if err != nil && err != sql.ErrNoRows {
+		return fmt.Errorf("failed to check for existing admin user: %w", err)
 	}
 
+	if adminUser != nil {
+		logging.Debug("Admin user already exists", "userId", adminUser.ID)
+		return nil
+	}
+
+	logging.Debug("Creating new admin user")
+
 	// Hash the password
-	hashedPassword, err := bcrypt.GenerateFromPassword([]byte(adminPassword), bcrypt.DefaultCost)
+	hashedPassword, err := bcrypt.GenerateFromPassword([]byte(cfg.AdminPassword), bcrypt.DefaultCost)
 	if err != nil {
-		return fmt.Errorf("failed to hash password: %w", err)
+		return fmt.Errorf("failed to hash admin password: %w", err)
 	}
 
 	// Create admin user
 	adminUser = &models.User{
-		Email:        adminEmail,
+		Email:        cfg.AdminEmail,
 		DisplayName:  "Admin",
 		PasswordHash: string(hashedPassword),
 		Role:         models.RoleAdmin,
@@ -102,13 +125,23 @@ func setupAdminUser(database db.Database, storageManager storage.Manager, cfg *C
 		return fmt.Errorf("failed to create admin user: %w", err)
 	}
 
+	logging.Debug("Admin user created",
+		"userId", createdUser.ID,
+		"workspaceId", createdUser.LastWorkspaceID)
+
 	// Initialize workspace directory
+	logging.Debug("Initializing admin workspace directory",
+		"userId", createdUser.ID,
+		"workspaceId", createdUser.LastWorkspaceID)
+
 	err = storageManager.InitializeUserWorkspace(createdUser.ID, createdUser.LastWorkspaceID)
 	if err != nil {
 		return fmt.Errorf("failed to initialize admin workspace: %w", err)
 	}
 
-	log.Printf("Created admin user with ID: %d and default workspace with ID: %d", createdUser.ID, createdUser.LastWorkspaceID)
+	logging.Info("Admin user setup completed",
+		"userId", createdUser.ID,
+		"workspaceId", createdUser.LastWorkspaceID)
 
 	return nil
 }

server/internal/app/routes.go

@@ -4,6 +4,7 @@ import (
 	"novamd/internal/auth"
 	"novamd/internal/context"
 	"novamd/internal/handlers"
+	"novamd/internal/logging"
 	"time"
 
 	"github.com/go-chi/chi/v5"
@@ -19,6 +20,7 @@ import (
 
 // setupRouter creates and configures the chi router with middleware and routes
 func setupRouter(o Options) *chi.Mux {
+	logging.Debug("Setting up router")
 	r := chi.NewRouter()
 
 	// Basic middleware
@@ -29,6 +31,7 @@ func setupRouter(o Options) *chi.Mux {
 	r.Use(middleware.Timeout(30 * time.Second))
 
 	// Security headers
+	logging.Debug("Setting up security headers")
 	r.Use(secure.New(secure.Options{
 		SSLRedirect:     false,
 		SSLProxyHeaders: map[string]string{"X-Forwarded-Proto": "https"},
@@ -36,6 +39,7 @@ func setupRouter(o Options) *chi.Mux {
 	}).Handler)
 
 	// CORS if origins are configured
+	logging.Debug("Setting up CORS")
 	if len(o.Config.CORSOrigins) > 0 {
 		r.Use(cors.Handler(cors.Options{
 			AllowedOrigins:   o.Config.CORSOrigins,
@@ -48,6 +52,7 @@ func setupRouter(o Options) *chi.Mux {
 	}
 
 	// Initialize auth middleware and handler
+	logging.Debug("Setting up authentication middleware")
 	authMiddleware := auth.NewMiddleware(o.JWTManager, o.SessionManager, o.CookieService)
 	handler := &handlers.Handler{
 		DB:      o.Database,
@@ -55,12 +60,14 @@ func setupRouter(o Options) *chi.Mux {
 	}
 
 	if o.Config.IsDevelopment {
+		logging.Debug("Setting up Swagger docs")
 		r.Get("/swagger/*", httpSwagger.Handler(
 			httpSwagger.URL("/swagger/doc.json"), // The URL pointing to API definition
 		))
 	}
 
 	// API routes
+	logging.Debug("Setting up API routes")
 	r.Route("/api/v1", func(r chi.Router) {
 		// Rate limiting for API routes
 		if o.Config.RateLimitRequests > 0 {
@@ -147,6 +154,7 @@ func setupRouter(o Options) *chi.Mux {
 	})
 
 	// Handle all other routes with static file server
+	logging.Debug("Setting up static file server")
 	r.Get("/*", handlers.NewStaticHandler(o.Config.StaticPath).ServeHTTP)
 
 	return r

server/internal/app/server.go

@@ -31,6 +31,7 @@ func (s *Server) Start() error {
 
 // Close handles graceful shutdown of server dependencies
 func (s *Server) Close() error {
+	logging.Info("Shutting down server")
 	return s.options.Database.Close()
 }