wip

Dockerfile.dev

@@ -7,13 +7,14 @@ COPY go.sum ./
 
 RUN go mod download
 
+RUN go install github.com/air-verse/air@v1.61.7
+RUN go install github.com/go-delve/delve/cmd/dlv@latest
+
 COPY ./cmd ./cmd
 COPY ./internal ./internal
 COPY ./main.go ./
 COPY ./air.toml ./
 
-RUN go install github.com/air-verse/air@v1.61.7
-
 EXPOSE 3000
 
 ENTRYPOINT ["air", "-c", "air.toml"]

air.toml

@@ -2,9 +2,9 @@ root = "/tinyauth"
 tmp_dir = "tmp"
 
 [build]
-pre_cmd = ["mkdir -p internal/assets/dist", "mkdir -p /data", "echo 'backend running' > internal/assets/dist/index.html", "go install github.com/go-delve/delve/cmd/dlv@v1.25.0"]
+pre_cmd = ["mkdir -p internal/assets/dist", "mkdir -p /data", "echo 'backend running' > internal/assets/dist/index.html", "cp /go/bin/dlv dlv"]
 cmd = "CGO_ENABLED=0 go build -gcflags=\"all=-N -l\" -o tmp/tinyauth ."
-bin = "/go/bin/dlv --listen :4000 --headless=true --api-version=2 --accept-multiclient --log=true exec tmp/tinyauth --continue --check-go-version=false"
+bin = "dlv --listen :4000 --headless=true --api-version=2 --accept-multiclient --log=true exec tmp/tinyauth --continue --check-go-version=false"
 include_ext = ["go"]
 exclude_dir = ["internal/assets/dist"]
 exclude_regex = [".*_test\\.go"]

cmd/root.go

@@ -71,6 +71,7 @@ func (c *rootCmd) Register() {
 		{"disable-analytics", false, "Disable anonymous version collection."},
 		{"disable-resources", false, "Disable the resources server."},
 		{"socket-path", "", "Path to the Unix socket to bind the server to."},
+		{"access-log-file", "", "Path to the access log file."},
 	}
 
 	for _, opt := range configOptions {

internal/bootstrap/app_bootstrap.go

@@ -48,6 +48,9 @@ func NewBootstrapApp(config config.Config) *BootstrapApp {
 }
 
 func (app *BootstrapApp) Setup() error {
+	// Log json
+	shoudLogJson := utils.ShoudLogJSON(os.Environ(), os.Args)
+
 	// Parse users
 	users, err := utils.GetUsers(app.config.Users, app.config.UsersFile)
 
@@ -142,6 +145,10 @@ func (app *BootstrapApp) Setup() error {
 	aclsService := service.NewAccessControlsService(dockerService)
 	authService := service.NewAuthService(authConfig, dockerService, ldapService, database)
 	oauthBrokerService := service.NewOAuthBrokerService(oauthProviders)
+	accessLogService := service.NewAccessLogService(&service.AccessLogServiceConfig{
+		LogFile: app.config.AccessLogFile,
+		LogJson: shoudLogJson,
+	})
 
 	// Initialize services (order matters)
 	services := []Service{
@@ -149,6 +156,7 @@ func (app *BootstrapApp) Setup() error {
 		aclsService,
 		authService,
 		oauthBrokerService,
+		accessLogService,
 	}
 
 	for _, svc := range services {
@@ -244,7 +252,7 @@ func (app *BootstrapApp) Setup() error {
 		CSRFCookieName:     csrfCookieName,
 		RedirectCookieName: redirectCookieName,
 		CookieDomain:       cookieDomain,
-	}, apiRouter, authService, oauthBrokerService)
+	}, apiRouter, authService, oauthBrokerService, accessLogService)
 
 	proxyController := controller.NewProxyController(controller.ProxyControllerConfig{
 		AppURL: app.config.AppURL,
@@ -252,7 +260,7 @@ func (app *BootstrapApp) Setup() error {
 
 	userController := controller.NewUserController(controller.UserControllerConfig{
 		CookieDomain: cookieDomain,
-	}, apiRouter, authService)
+	}, apiRouter, authService, accessLogService)
 
 	resourcesController := controller.NewResourcesController(controller.ResourcesControllerConfig{
 		ResourcesDir:      app.config.ResourcesDir,
@@ -375,7 +383,8 @@ func (app *BootstrapApp) dbCleanup(db *gorm.DB) {
 
 	for ; true; <-ticker.C {
 		log.Debug().Msg("Cleaning up old database sessions")
-		_, err := gorm.G[model.Session](db).Where("expiry < ?", time.Now().UnixMilli()).Delete(ctx)
+		rows, err := gorm.G[model.Session](db).Where("expiry < ?", time.Now().UnixMilli()).Delete(ctx)
+		log.Debug().Int("rows_affected", rows).Msg("Old sessions cleanup completed")
 		if err != nil {
 			log.Error().Err(err).Msg("Failed to cleanup old sessions")
 		}

internal/config/config.go

@@ -42,6 +42,7 @@ type Config struct {
 	DisableAnalytics      bool   `mapstructure:"disable-analytics"`
 	DisableResources      bool   `mapstructure:"disable-resources"`
 	SocketPath            string `mapstructure:"socket-path"`
+	AccessLogFile         string `mapstructure:"access-log-file"`
 }
 
 // OAuth/OIDC config

internal/controller/oauth_controller.go

@@ -31,14 +31,16 @@ type OAuthController struct {
 	router *gin.RouterGroup
 	auth   *service.AuthService
 	broker *service.OAuthBrokerService
+	als    *service.AccessLogService
 }
 
-func NewOAuthController(config OAuthControllerConfig, router *gin.RouterGroup, auth *service.AuthService, broker *service.OAuthBrokerService) *OAuthController {
+func NewOAuthController(config OAuthControllerConfig, router *gin.RouterGroup, auth *service.AuthService, broker *service.OAuthBrokerService, als *service.AccessLogService) *OAuthController {
 	return &OAuthController{
 		config: config,
 		router: router,
 		auth:   auth,
 		broker: broker,
+		als:    als,
 	}
 }
 
@@ -61,7 +63,7 @@ func (controller *OAuthController) oauthURLHandler(c *gin.Context) {
 		return
 	}
 
-	service, exists := controller.broker.GetService(req.Provider)
+	svc, exists := controller.broker.GetService(req.Provider)
 
 	if !exists {
 		log.Warn().Msgf("OAuth provider not found: %s", req.Provider)
@@ -72,9 +74,9 @@ func (controller *OAuthController) oauthURLHandler(c *gin.Context) {
 		return
 	}
 
-	service.GenerateVerifier()
-	state := service.GenerateState()
-	authURL := service.GetAuthURL(state)
+	svc.GenerateVerifier()
+	state := svc.GenerateState()
+	authURL := svc.GetAuthURL(state)
 	c.SetCookie(controller.config.CSRFCookieName, state, int(time.Hour.Seconds()), "/", fmt.Sprintf(".%s", controller.config.CookieDomain), controller.config.SecureCookie, true)
 
 	redirectURI := c.Query("redirect_uri")
@@ -106,8 +108,16 @@ func (controller *OAuthController) oauthCallbackHandler(c *gin.Context) {
 
 	state := c.Query("state")
 	csrfCookie, err := c.Cookie(controller.config.CSRFCookieName)
+	clientIP := c.ClientIP()
 
 	if err != nil || state != csrfCookie {
+		controller.als.Log(service.AccessLog{
+			Provider: req.Provider,
+			Username: "",
+			ClientIP: clientIP,
+			Success:  false,
+			Message:  "CSRF token mismatch or cookie missing",
+		})
 		log.Warn().Err(err).Msg("CSRF token mismatch or cookie missing")
 		c.SetCookie(controller.config.CSRFCookieName, "", -1, "/", fmt.Sprintf(".%s", controller.config.CookieDomain), controller.config.SecureCookie, true)
 		c.Redirect(http.StatusTemporaryRedirect, fmt.Sprintf("%s/error", controller.config.AppURL))
@@ -117,16 +127,30 @@ func (controller *OAuthController) oauthCallbackHandler(c *gin.Context) {
 	c.SetCookie(controller.config.CSRFCookieName, "", -1, "/", fmt.Sprintf(".%s", controller.config.CookieDomain), controller.config.SecureCookie, true)
 
 	code := c.Query("code")
-	service, exists := controller.broker.GetService(req.Provider)
+	svc, exists := controller.broker.GetService(req.Provider)
 
 	if !exists {
+		controller.als.Log(service.AccessLog{
+			Provider: req.Provider,
+			Username: "",
+			ClientIP: clientIP,
+			Success:  false,
+			Message:  "OAuth provider not found",
+		})
 		log.Warn().Msgf("OAuth provider not found: %s", req.Provider)
 		c.Redirect(http.StatusTemporaryRedirect, fmt.Sprintf("%s/error", controller.config.AppURL))
 		return
 	}
 
-	err = service.VerifyCode(code)
+	err = svc.VerifyCode(code)
 	if err != nil {
+		controller.als.Log(service.AccessLog{
+			Provider: req.Provider,
+			Username: "",
+			ClientIP: clientIP,
+			Success:  false,
+			Message:  "Failed to verify OAuth code",
+		})
 		log.Error().Err(err).Msg("Failed to verify OAuth code")
 		c.Redirect(http.StatusTemporaryRedirect, fmt.Sprintf("%s/error", controller.config.AppURL))
 		return
@@ -147,6 +171,14 @@ func (controller *OAuthController) oauthCallbackHandler(c *gin.Context) {
 	}
 
 	if !controller.auth.IsEmailWhitelisted(user.Email) {
+		controller.als.Log(service.AccessLog{
+			Provider: req.Provider,
+			Username: user.Email,
+			ClientIP: clientIP,
+			Success:  false,
+			Message:  "Email not whitelisted",
+		})
+
 		log.Warn().Str("email", user.Email).Msg("Email not whitelisted")
 
 		queries, err := query.Values(config.UnauthorizedQuery{
@@ -189,7 +221,7 @@ func (controller *OAuthController) oauthCallbackHandler(c *gin.Context) {
 		Email:       user.Email,
 		Provider:    req.Provider,
 		OAuthGroups: utils.CoalesceToString(user.Groups),
-		OAuthName:   service.GetName(),
+		OAuthName:   svc.GetName(),
 	}
 
 	log.Trace().Interface("session_cookie", sessionCookie).Msg("Creating session cookie")
@@ -202,6 +234,14 @@ func (controller *OAuthController) oauthCallbackHandler(c *gin.Context) {
 		return
 	}
 
+	controller.als.Log(service.AccessLog{
+		Provider: req.Provider,
+		Username: user.Email,
+		ClientIP: clientIP,
+		Success:  true,
+		Message:  "OAuth login successful",
+	})
+
 	redirectURI, err := c.Cookie(controller.config.RedirectCookieName)
 
 	if err != nil || !utils.IsRedirectSafe(redirectURI, controller.config.CookieDomain) {

internal/controller/user_controller.go

@@ -29,13 +29,15 @@ type UserController struct {
 	config UserControllerConfig
 	router *gin.RouterGroup
 	auth   *service.AuthService
+	als    *service.AccessLogService
 }
 
-func NewUserController(config UserControllerConfig, router *gin.RouterGroup, auth *service.AuthService) *UserController {
+func NewUserController(config UserControllerConfig, router *gin.RouterGroup, auth *service.AuthService, als *service.AccessLogService) *UserController {
 	return &UserController{
 		config: config,
 		router: router,
 		auth:   auth,
+		als:    als,
 	}
 }
 
@@ -72,6 +74,13 @@ func (controller *UserController) loginHandler(c *gin.Context) {
 	isLocked, remainingTime := controller.auth.IsAccountLocked(rateIdentifier)
 
 	if isLocked {
+		controller.als.Log(service.AccessLog{
+			Provider: "username",
+			Username: req.Username,
+			ClientIP: clientIP,
+			Success:  false,
+			Message:  "Account is locked due to too many failed login attempts",
+		})
 		log.Warn().Str("username", req.Username).Str("ip", clientIP).Msg("Account is locked due to too many failed login attempts")
 		c.JSON(429, gin.H{
 			"status":  429,
@@ -83,6 +92,13 @@ func (controller *UserController) loginHandler(c *gin.Context) {
 	userSearch := controller.auth.SearchUser(req.Username)
 
 	if userSearch.Type == "unknown" {
+		controller.als.Log(service.AccessLog{
+			Provider: "username",
+			Username: req.Username,
+			ClientIP: clientIP,
+			Success:  false,
+			Message:  "User not found",
+		})
 		log.Warn().Str("username", req.Username).Str("ip", clientIP).Msg("User not found")
 		controller.auth.RecordLoginAttempt(rateIdentifier, false)
 		c.JSON(401, gin.H{
@@ -93,6 +109,13 @@ func (controller *UserController) loginHandler(c *gin.Context) {
 	}
 
 	if !controller.auth.VerifyUser(userSearch, req.Password) {
+		controller.als.Log(service.AccessLog{
+			Provider: "username",
+			Username: req.Username,
+			ClientIP: clientIP,
+			Success:  false,
+			Message:  "Invalid password",
+		})
 		log.Warn().Str("username", req.Username).Str("ip", clientIP).Msg("Invalid password")
 		controller.auth.RecordLoginAttempt(rateIdentifier, false)
 		c.JSON(401, gin.H{
@@ -102,14 +125,18 @@ func (controller *UserController) loginHandler(c *gin.Context) {
 		return
 	}
 
-	log.Info().Str("username", req.Username).Str("ip", clientIP).Msg("Login successful")
-
-	controller.auth.RecordLoginAttempt(rateIdentifier, true)
-
 	if userSearch.Type == "local" {
 		user := controller.auth.GetLocalUser(userSearch.Username)
 
 		if user.TotpSecret != "" {
+			controller.als.Log(service.AccessLog{
+				Provider: "username",
+				Username: req.Username,
+				ClientIP: clientIP,
+				Success:  true,
+				Message:  "User has TOTP enabled, requiring TOTP verification",
+			})
+
 			log.Debug().Str("username", req.Username).Msg("User has TOTP enabled, requiring TOTP verification")
 
 			err := controller.auth.CreateSessionCookie(c, &config.SessionCookie{
@@ -158,6 +185,18 @@ func (controller *UserController) loginHandler(c *gin.Context) {
 		return
 	}
 
+	controller.als.Log(service.AccessLog{
+		Provider: "username",
+		Username: req.Username,
+		ClientIP: clientIP,
+		Success:  true,
+		Message:  "Login successful",
+	})
+
+	log.Info().Str("username", req.Username).Str("ip", clientIP).Msg("Login successful")
+
+	controller.auth.RecordLoginAttempt(rateIdentifier, true)
+
 	c.JSON(200, gin.H{
 		"status":  200,
 		"message": "Login successful",
@@ -167,8 +206,28 @@ func (controller *UserController) loginHandler(c *gin.Context) {
 func (controller *UserController) logoutHandler(c *gin.Context) {
 	log.Debug().Msg("Logout request received")
 
+	context, err := utils.GetContext(c)
+
+	if err != nil {
+		log.Debug().Msg("Not logged in, nothing to do")
+		c.JSON(200, gin.H{
+			"status":  200,
+			"message": "Not logged in",
+		})
+		return
+	}
+
+	clientIP := c.ClientIP()
 	controller.auth.DeleteSessionCookie(c)
 
+	controller.als.Log(service.AccessLog{
+		Provider: "username",
+		Username: context.Username,
+		ClientIP: clientIP,
+		Success:  true,
+		Message:  "Logout successful",
+	})
+
 	c.JSON(200, gin.H{
 		"status":  200,
 		"message": "Logout successful",
@@ -188,6 +247,7 @@ func (controller *UserController) totpHandler(c *gin.Context) {
 		return
 	}
 
+	clientIP := c.ClientIP()
 	context, err := utils.GetContext(c)
 
 	if err != nil {
@@ -208,8 +268,6 @@ func (controller *UserController) totpHandler(c *gin.Context) {
 		return
 	}
 
-	clientIP := c.ClientIP()
-
 	rateIdentifier := context.Username
 
 	if rateIdentifier == "" {
@@ -221,6 +279,13 @@ func (controller *UserController) totpHandler(c *gin.Context) {
 	isLocked, remainingTime := controller.auth.IsAccountLocked(rateIdentifier)
 
 	if isLocked {
+		controller.als.Log(service.AccessLog{
+			Provider: "username",
+			Username: context.Username,
+			ClientIP: clientIP,
+			Success:  false,
+			Message:  "Account is locked due to too many failed TOTP attempts",
+		})
 		log.Warn().Str("username", context.Username).Str("ip", clientIP).Msg("Account is locked due to too many failed TOTP attempts")
 		c.JSON(429, gin.H{
 			"status":  429,
@@ -234,6 +299,13 @@ func (controller *UserController) totpHandler(c *gin.Context) {
 	ok := totp.Validate(req.Code, user.TotpSecret)
 
 	if !ok {
+		controller.als.Log(service.AccessLog{
+			Provider: "username",
+			Username: context.Username,
+			ClientIP: clientIP,
+			Success:  false,
+			Message:  "Invalid TOTP code",
+		})
 		log.Warn().Str("username", context.Username).Str("ip", clientIP).Msg("Invalid TOTP code")
 		controller.auth.RecordLoginAttempt(rateIdentifier, false)
 		c.JSON(401, gin.H{
@@ -243,6 +315,14 @@ func (controller *UserController) totpHandler(c *gin.Context) {
 		return
 	}
 
+	controller.als.Log(service.AccessLog{
+		Provider: "username",
+		Username: context.Username,
+		ClientIP: clientIP,
+		Success:  true,
+		Message:  "TOTP verification successful",
+	})
+
 	log.Info().Str("username", context.Username).Str("ip", clientIP).Msg("TOTP verification successful")
 
 	controller.auth.RecordLoginAttempt(rateIdentifier, true)

internal/controller/user_controller_test.go

@@ -64,10 +64,18 @@ func setupUserController(t *testing.T, middlewares *[]gin.HandlerFunc) (*gin.Eng
 		SessionCookieName: "tinyauth-session",
 	}, nil, nil, database)
 
+	// Access log service
+	als := service.NewAccessLogService(&service.AccessLogServiceConfig{
+		LogFile: "",
+		LogJson: true,
+	})
+
+	assert.NilError(t, als.Init())
+
 	// Controller
 	ctrl := controller.NewUserController(controller.UserControllerConfig{
 		CookieDomain: "localhost",
-	}, group, authService)
+	}, group, authService, als)
 	ctrl.SetupRoutes()
 
 	return router, recorder

internal/service/access_log_service.go

@@ -0,0 +1,96 @@
+package service
+
+import (
+	"fmt"
+	"io"
+	"os"
+	"strings"
+	"time"
+
+	"github.com/rs/zerolog"
+)
+
+type AccessLog struct {
+	Provider string
+	Username string
+	ClientIP string
+	Success  bool
+	Message  string
+}
+
+type AccessLogServiceConfig struct {
+	LogFile string
+	LogJson bool
+}
+
+type AccessLogService struct {
+	config *AccessLogServiceConfig
+	logger zerolog.Logger
+}
+
+func NewAccessLogService(config *AccessLogServiceConfig) *AccessLogService {
+	return &AccessLogService{
+		config: config,
+	}
+}
+
+func (als *AccessLogService) Init() error {
+	writers := make([]io.Writer, 0)
+
+	if als.config.LogFile != "" {
+		// We are not closing the file here since we will keep writing to it until interrupted
+		file, err := os.OpenFile(als.config.LogFile, os.O_RDWR|os.O_CREATE|os.O_TRUNC, 0640)
+		if err != nil {
+			return err
+		}
+		writter := zerolog.ConsoleWriter(zerolog.ConsoleWriter{Out: file, TimeFormat: time.RFC3339, NoColor: true, PartsOrder: []string{
+			"time", "level", "caller", "message",
+		}})
+		writter.FormatLevel = func(i any) string {
+			return strings.ToUpper(fmt.Sprintf("[ %s ]", i))
+		}
+		writter.FormatCaller = func(i any) string {
+			return fmt.Sprintf("%s:", i)
+		}
+		writter.FormatMessage = func(i any) string {
+			return fmt.Sprintf("%s", i)
+		}
+		writter.FormatFieldName = func(i any) string {
+			return fmt.Sprintf("%s=", i)
+		}
+		writter.FormatFieldValue = func(i any) string {
+			return fmt.Sprintf("%s", i)
+		}
+		writers = append(writers, writter)
+	}
+
+	if !als.config.LogJson {
+		writter := zerolog.ConsoleWriter(zerolog.ConsoleWriter{Out: os.Stdout, TimeFormat: time.RFC3339})
+		writers = append(writers, writter)
+	} else {
+		writers = append(writers, os.Stdout)
+	}
+
+	als.logger = zerolog.New(zerolog.MultiLevelWriter(writers...)).With().Caller().Logger()
+
+	return nil
+}
+
+func (als *AccessLogService) Log(log AccessLog) {
+	var event *zerolog.Event
+
+	if log.Success {
+		event = als.logger.Info()
+	} else {
+		event = als.logger.Warn()
+	}
+
+	event = event.
+		Str("provider", log.Provider).
+		Str("username", log.Username).
+		Str("client_ip", log.ClientIP).
+		Int64("time", time.Now().UnixMilli()).
+		Bool("success", log.Success)
+
+	event.Msg(log.Message)
+}

internal/service/auth_service.go

@@ -213,7 +213,7 @@ func (auth *AuthService) CreateSessionCookie(c *gin.Context, data *config.Sessio
 		Provider:    data.Provider,
 		TOTPPending: data.TotpPending,
 		OAuthGroups: data.OAuthGroups,
-		Expiry:      time.Now().Add(time.Duration(expiry) * time.Second).Unix(),
+		Expiry:      time.Now().Add(time.Duration(expiry) * time.Second).UnixMilli(),
 		OAuthName:   data.OAuthName,
 	}
 
@@ -263,12 +263,12 @@ func (auth *AuthService) GetSessionCookie(c *gin.Context) (config.SessionCookie,
 		return config.SessionCookie{}, fmt.Errorf("session not found")
 	}
 
-	currentTime := time.Now().Unix()
+	currentTime := time.Now().UnixMilli()
 
 	if currentTime > session.Expiry {
-		res := auth.database.Unscoped().Where("uuid = ?", session.UUID).Delete(&model.Session{})
-		if res.Error != nil {
-			log.Error().Err(res.Error).Msg("Failed to delete expired session")
+		_, err = gorm.G[model.Session](auth.database).Where("uuid = ?", cookie).Delete(auth.ctx)
+		if err != nil {
+			log.Error().Err(err).Msg("Failed to delete expired session")
 		}
 		return config.SessionCookie{}, fmt.Errorf("session expired")
 	}

main.go

@@ -11,7 +11,7 @@ import (
 )
 
 func main() {
-	log.Logger = log.Logger.With().Timestamp().Caller().Logger()
+	log.Logger = log.Logger.With().Caller().Logger()
 	if !utils.ShoudLogJSON(os.Environ(), os.Args) {
 		log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stderr, TimeFormat: time.RFC3339})
 	}