From bc3b0fda357cb8a3c0e592cfac0c1a9365ab78ef Mon Sep 17 00:00:00 2001 From: James Elliott Date: Mon, 29 Nov 2021 14:09:14 +1100 Subject: [PATCH] feat(regulator): enhance authentication logs (#2622) This adds additional logging to the authentication logs such as type, remote IP, request method, redirect URL, and if the attempt was done during a ban. This also means we log attempts that occur when the attempt was blocked by the regulator for record keeping purposes, as well as record 2FA attempts which can be used to inform admins and later to regulate based on other factors. Fixes #116, Fixes #1293. --- internal/handlers/const.go | 11 +++ internal/handlers/handler_firstfactor.go | 83 ++++++++++--------- internal/handlers/handler_firstfactor_test.go | 51 ++++++++++-- internal/handlers/handler_sign_duo.go | 42 +++++++--- internal/handlers/handler_sign_duo_test.go | 81 +++++++++++++++++- internal/handlers/handler_sign_totp.go | 46 ++++++---- internal/handlers/handler_sign_totp_test.go | 56 +++++++++++++ internal/handlers/handler_sign_u2f_step1.go | 52 ++++++++---- internal/handlers/handler_sign_u2f_step2.go | 55 ++++++++---- .../handlers/handler_sign_u2f_step2_test.go | 57 +++++++++++++ internal/handlers/handler_user_info_test.go | 6 +- internal/handlers/response.go | 39 +++++++-- internal/middlewares/authelia_context.go | 14 +++- .../models/model_authentication_attempt.go | 1 + internal/models/type_ipaddress.go | 6 ++ internal/regulation/const.go | 17 ++++ internal/regulation/regulator.go | 14 +++- .../session/encrypting_serializer_test.go | 1 - .../V0001.Initial_Schema.mysql.up.sql | 11 ++- .../V0001.Initial_Schema.postgres.up.sql | 9 +- .../V0001.Initial_Schema.sqlite.up.sql | 11 ++- internal/storage/sql_provider.go | 6 +- internal/storage/sql_provider_queries.go | 6 +- .../storage/sql_provider_queries_special.go | 4 +- 24 files changed, 537 insertions(+), 142 deletions(-) diff --git a/internal/handlers/const.go b/internal/handlers/const.go index f8a1bea28..b99751639 100644 --- a/internal/handlers/const.go +++ b/internal/handlers/const.go @@ -45,6 +45,17 @@ const ( messageMFAValidationFailed = "Authentication failed, please retry later." ) +const ( + logFmtErrParseRequestBody = "Failed to parse %s request body: %+v" + logFmtErrWriteResponseBody = "Failed to write %s response body for user '%s': %+v" + logFmtErrRegulationFail = "Failed to perform %s authentication regulation for user '%s': %+v" + logFmtErrSessionRegenerate = "Could not regenerate session during %s authentication for user '%s': %+v" + logFmtErrSessionReset = "Could not reset session during %s authentication for user '%s': %+v" + logFmtErrSessionSave = "Could not save session with the %s during %s authentication for user '%s': %+v" + logFmtErrObtainProfileDetails = "Could not obtain profile details during %s authentication for user '%s': %+v" + logFmtTraceProfileDetails = "Profile details for user '%s' => groups: %s, emails %s" +) + const ( testInactivity = "10" testRedirectionURL = "http://redirection.local" diff --git a/internal/handlers/handler_firstfactor.go b/internal/handlers/handler_firstfactor.go index a6023b6f4..2b02f1f23 100644 --- a/internal/handlers/handler_firstfactor.go +++ b/internal/handlers/handler_firstfactor.go @@ -1,7 +1,7 @@ package handlers import ( - "fmt" + "errors" "math" "math/rand" "sync" @@ -70,78 +70,72 @@ func FirstFactorPost(msInitialDelay time.Duration, delayEnabled bool) middleware } bodyJSON := firstFactorRequestBody{} - err := ctx.ParseBody(&bodyJSON) - if err != nil { - handleAuthenticationUnauthorized(ctx, err, messageAuthenticationFailed) + if err := ctx.ParseBody(&bodyJSON); err != nil { + ctx.Logger.Errorf(logFmtErrParseRequestBody, regulation.AuthType1FA, err) + + respondUnauthorized(ctx, messageAuthenticationFailed) + return } - bannedUntil, err := ctx.Providers.Regulator.Regulate(ctx, bodyJSON.Username) + if bannedUntil, err := ctx.Providers.Regulator.Regulate(ctx, bodyJSON.Username); err != nil { + if errors.Is(err, regulation.ErrUserIsBanned) { + _ = markAuthenticationAttempt(ctx, false, &bannedUntil, bodyJSON.Username, regulation.AuthType1FA, nil) + + respondUnauthorized(ctx, messageAuthenticationFailed) - if err != nil { - if err == regulation.ErrUserIsBanned { - handleAuthenticationUnauthorized(ctx, fmt.Errorf("user %s is banned until %s", bodyJSON.Username, bannedUntil), messageAuthenticationFailed) return } - handleAuthenticationUnauthorized(ctx, fmt.Errorf("unable to regulate authentication: %s", err.Error()), messageAuthenticationFailed) + ctx.Logger.Errorf(logFmtErrRegulationFail, regulation.AuthType1FA, bodyJSON.Username, err) + + respondUnauthorized(ctx, messageAuthenticationFailed) return } userPasswordOk, err := ctx.Providers.UserProvider.CheckUserPassword(bodyJSON.Username, bodyJSON.Password) - if err != nil { - ctx.Logger.Debugf("Mark authentication attempt made by user %s", bodyJSON.Username) + _ = markAuthenticationAttempt(ctx, false, nil, bodyJSON.Username, regulation.AuthType1FA, err) - if err := ctx.Providers.Regulator.Mark(ctx, bodyJSON.Username, false); err != nil { - ctx.Logger.Errorf("Unable to mark authentication: %s", err.Error()) - } - - handleAuthenticationUnauthorized(ctx, fmt.Errorf("error while checking password for user %s: %s", bodyJSON.Username, err.Error()), messageAuthenticationFailed) + respondUnauthorized(ctx, messageAuthenticationFailed) return } if !userPasswordOk { - ctx.Logger.Debugf("Mark authentication attempt made by user %s", bodyJSON.Username) + _ = markAuthenticationAttempt(ctx, false, nil, bodyJSON.Username, regulation.AuthType1FA, nil) - if err := ctx.Providers.Regulator.Mark(ctx, bodyJSON.Username, false); err != nil { - ctx.Logger.Errorf("Unable to mark authentication: %s", err.Error()) - } - - handleAuthenticationUnauthorized(ctx, fmt.Errorf("credentials are wrong for user %s", bodyJSON.Username), messageAuthenticationFailed) + respondUnauthorized(ctx, messageAuthenticationFailed) return } - ctx.Logger.Debugf("Mark authentication attempt made by user %s", bodyJSON.Username) - err = ctx.Providers.Regulator.Mark(ctx, bodyJSON.Username, true) + if err = markAuthenticationAttempt(ctx, true, nil, bodyJSON.Username, regulation.AuthType1FA, nil); err != nil { + respondUnauthorized(ctx, messageAuthenticationFailed) - if err != nil { - handleAuthenticationUnauthorized(ctx, fmt.Errorf("unable to mark authentication: %s", err.Error()), messageAuthenticationFailed) return } - ctx.Logger.Debugf("Credentials validation of user %s is ok", bodyJSON.Username) - userSession := ctx.GetSession() newSession := session.NewDefaultUserSession() newSession.OIDCWorkflowSession = userSession.OIDCWorkflowSession // Reset all values from previous session except OIDC workflow before regenerating the cookie. - err = ctx.SaveSession(newSession) + if err = ctx.SaveSession(newSession); err != nil { + ctx.Logger.Errorf(logFmtErrSessionReset, regulation.AuthType1FA, bodyJSON.Username, err) + + respondUnauthorized(ctx, messageAuthenticationFailed) - if err != nil { - handleAuthenticationUnauthorized(ctx, fmt.Errorf("unable to reset the session for user %s: %s", bodyJSON.Username, err.Error()), messageAuthenticationFailed) return } - err = ctx.Providers.SessionProvider.RegenerateSession(ctx.RequestCtx) + if err = ctx.Providers.SessionProvider.RegenerateSession(ctx.RequestCtx); err != nil { + ctx.Logger.Errorf(logFmtErrSessionRegenerate, regulation.AuthType1FA, bodyJSON.Username, err) + + respondUnauthorized(ctx, messageAuthenticationFailed) - if err != nil { - handleAuthenticationUnauthorized(ctx, fmt.Errorf("unable to regenerate session for user %s: %s", bodyJSON.Username, err.Error()), messageAuthenticationFailed) return } @@ -152,20 +146,25 @@ func FirstFactorPost(msInitialDelay time.Duration, delayEnabled bool) middleware if keepMeLoggedIn { err = ctx.Providers.SessionProvider.UpdateExpiration(ctx.RequestCtx, ctx.Providers.SessionProvider.RememberMe) if err != nil { - handleAuthenticationUnauthorized(ctx, fmt.Errorf("unable to update expiration timer for user %s: %s", bodyJSON.Username, err.Error()), messageAuthenticationFailed) + ctx.Logger.Errorf(logFmtErrSessionSave, "updated expiration", regulation.AuthType1FA, bodyJSON.Username, err) + + respondUnauthorized(ctx, messageAuthenticationFailed) + return } } // Get the details of the given user from the user provider. userDetails, err := ctx.Providers.UserProvider.GetDetails(bodyJSON.Username) - if err != nil { - handleAuthenticationUnauthorized(ctx, fmt.Errorf("error while retrieving details from user %s: %s", bodyJSON.Username, err.Error()), messageAuthenticationFailed) + ctx.Logger.Errorf(logFmtErrObtainProfileDetails, regulation.AuthType1FA, bodyJSON.Username, err) + + respondUnauthorized(ctx, messageAuthenticationFailed) + return } - ctx.Logger.Tracef("Details for user %s => groups: %s, emails %s", bodyJSON.Username, userDetails.Groups, userDetails.Emails) + ctx.Logger.Tracef(logFmtTraceProfileDetails, bodyJSON.Username, userDetails.Groups, userDetails.Emails) userSession.SetOneFactor(ctx.Clock.Now(), userDetails, keepMeLoggedIn) @@ -173,9 +172,11 @@ func FirstFactorPost(msInitialDelay time.Duration, delayEnabled bool) middleware userSession.RefreshTTL = ctx.Clock.Now().Add(refreshInterval) } - err = ctx.SaveSession(userSession) - if err != nil { - handleAuthenticationUnauthorized(ctx, fmt.Errorf("unable to save session of user %s", bodyJSON.Username), messageAuthenticationFailed) + if err = ctx.SaveSession(userSession); err != nil { + ctx.Logger.Errorf(logFmtErrSessionSave, "updated profile", regulation.AuthType1FA, bodyJSON.Username, err) + + respondUnauthorized(ctx, messageAuthenticationFailed) + return } diff --git a/internal/handlers/handler_firstfactor_test.go b/internal/handlers/handler_firstfactor_test.go index bcfc5f34a..616eb1591 100644 --- a/internal/handlers/handler_firstfactor_test.go +++ b/internal/handlers/handler_firstfactor_test.go @@ -15,6 +15,7 @@ import ( "github.com/authelia/authelia/v4/internal/configuration/schema" "github.com/authelia/authelia/v4/internal/mocks" "github.com/authelia/authelia/v4/internal/models" + "github.com/authelia/authelia/v4/internal/regulation" ) type FirstFactorSuite struct { @@ -35,7 +36,7 @@ func (s *FirstFactorSuite) TestShouldFailIfBodyIsNil() { FirstFactorPost(0, false)(s.mock.Ctx) // No body - assert.Equal(s.T(), "Unable to parse body: unexpected end of JSON input", s.mock.Hook.LastEntry().Message) + assert.Equal(s.T(), "Failed to parse 1FA request body: unable to parse body: unexpected end of JSON input", s.mock.Hook.LastEntry().Message) s.mock.Assert401KO(s.T(), "Authentication failed. Check your credentials.") } @@ -46,7 +47,7 @@ func (s *FirstFactorSuite) TestShouldFailIfBodyIsInBadFormat() { }`) FirstFactorPost(0, false)(s.mock.Ctx) - assert.Equal(s.T(), "Unable to validate body: password: non zero value required", s.mock.Hook.LastEntry().Message) + assert.Equal(s.T(), "Failed to parse 1FA request body: unable to validate body: password: non zero value required", s.mock.Hook.LastEntry().Message) s.mock.Assert401KO(s.T(), "Authentication failed. Check your credentials.") } @@ -54,14 +55,17 @@ func (s *FirstFactorSuite) TestShouldFailIfUserProviderCheckPasswordFail() { s.mock.UserProviderMock. EXPECT(). CheckUserPassword(gomock.Eq("test"), gomock.Eq("hello")). - Return(false, fmt.Errorf("Failed")) + Return(false, fmt.Errorf("failed")) s.mock.StorageProviderMock. EXPECT(). AppendAuthenticationLog(s.mock.Ctx, gomock.Eq(models.AuthenticationAttempt{ Username: "test", Successful: false, + Banned: false, Time: s.mock.Clock.Now(), + Type: regulation.AuthType1FA, + RemoteIP: models.NewIPAddressFromString("0.0.0.0"), })) s.mock.Ctx.Request.SetBodyString(`{ @@ -71,22 +75,51 @@ func (s *FirstFactorSuite) TestShouldFailIfUserProviderCheckPasswordFail() { }`) FirstFactorPost(0, false)(s.mock.Ctx) - assert.Equal(s.T(), "error while checking password for user test: Failed", s.mock.Hook.LastEntry().Message) + assert.Equal(s.T(), "Unsuccessful 1FA authentication attempt by user 'test': failed", s.mock.Hook.LastEntry().Message) s.mock.Assert401KO(s.T(), "Authentication failed. Check your credentials.") } -func (s *FirstFactorSuite) TestShouldCheckAuthenticationIsMarkedWhenInvalidCredentials() { +func (s *FirstFactorSuite) TestShouldCheckAuthenticationIsNotMarkedWhenProviderCheckPasswordError() { s.mock.UserProviderMock. EXPECT(). CheckUserPassword(gomock.Eq("test"), gomock.Eq("hello")). - Return(false, fmt.Errorf("Invalid credentials")) + Return(false, fmt.Errorf("invalid credentials")) s.mock.StorageProviderMock. EXPECT(). AppendAuthenticationLog(s.mock.Ctx, gomock.Eq(models.AuthenticationAttempt{ Username: "test", Successful: false, + Banned: false, Time: s.mock.Clock.Now(), + Type: regulation.AuthType1FA, + RemoteIP: models.NewIPAddressFromString("0.0.0.0"), + })) + + s.mock.Ctx.Request.SetBodyString(`{ + "username": "test", + "password": "hello", + "keepMeLoggedIn": true + }`) + + FirstFactorPost(0, false)(s.mock.Ctx) +} + +func (s *FirstFactorSuite) TestShouldCheckAuthenticationIsMarkedWhenInvalidCredentials() { + s.mock.UserProviderMock. + EXPECT(). + CheckUserPassword(gomock.Eq("test"), gomock.Eq("hello")). + Return(false, nil) + + s.mock.StorageProviderMock. + EXPECT(). + AppendAuthenticationLog(s.mock.Ctx, gomock.Eq(models.AuthenticationAttempt{ + Username: "test", + Successful: false, + Banned: false, + Time: s.mock.Clock.Now(), + Type: regulation.AuthType1FA, + RemoteIP: models.NewIPAddressFromString("0.0.0.0"), })) s.mock.Ctx.Request.SetBodyString(`{ @@ -112,7 +145,7 @@ func (s *FirstFactorSuite) TestShouldFailIfUserProviderGetDetailsFail() { s.mock.UserProviderMock. EXPECT(). GetDetails(gomock.Eq("test")). - Return(nil, fmt.Errorf("Failed")) + Return(nil, fmt.Errorf("failed")) s.mock.Ctx.Request.SetBodyString(`{ "username": "test", @@ -121,7 +154,7 @@ func (s *FirstFactorSuite) TestShouldFailIfUserProviderGetDetailsFail() { }`) FirstFactorPost(0, false)(s.mock.Ctx) - assert.Equal(s.T(), "error while retrieving details from user test: Failed", s.mock.Hook.LastEntry().Message) + assert.Equal(s.T(), "Could not obtain profile details during 1FA authentication for user 'test': failed", s.mock.Hook.LastEntry().Message) s.mock.Assert401KO(s.T(), "Authentication failed. Check your credentials.") } @@ -143,7 +176,7 @@ func (s *FirstFactorSuite) TestShouldFailIfAuthenticationMarkFail() { }`) FirstFactorPost(0, false)(s.mock.Ctx) - assert.Equal(s.T(), "unable to mark authentication: failed", s.mock.Hook.LastEntry().Message) + assert.Equal(s.T(), "Unable to mark 1FA authentication attempt by user 'test': failed", s.mock.Hook.LastEntry().Message) s.mock.Assert401KO(s.T(), "Authentication failed. Check your credentials.") } diff --git a/internal/handlers/handler_sign_duo.go b/internal/handlers/handler_sign_duo.go index 2b8f6ec80..0531bec3d 100644 --- a/internal/handlers/handler_sign_duo.go +++ b/internal/handlers/handler_sign_duo.go @@ -6,26 +6,29 @@ import ( "github.com/authelia/authelia/v4/internal/duo" "github.com/authelia/authelia/v4/internal/middlewares" + "github.com/authelia/authelia/v4/internal/regulation" ) // SecondFactorDuoPost handler for sending a push notification via duo api. func SecondFactorDuoPost(duoAPI duo.API) middlewares.RequestHandler { return func(ctx *middlewares.AutheliaCtx) { var requestBody signDuoRequestBody - err := ctx.ParseBody(&requestBody) - if err != nil { - handleAuthenticationUnauthorized(ctx, err, messageMFAValidationFailed) + if err := ctx.ParseBody(&requestBody); err != nil { + ctx.Logger.Errorf(logFmtErrParseRequestBody, regulation.AuthTypeDUO, err) + + respondUnauthorized(ctx, messageMFAValidationFailed) + return } userSession := ctx.GetSession() remoteIP := ctx.RemoteIP().String() - ctx.Logger.Debugf("Starting Duo Push Auth Attempt for %s from IP %s", userSession.Username, remoteIP) + ctx.Logger.Debugf("Starting Duo Push Auth Attempt for user '%s' with IP '%s'", userSession.Username, remoteIP) values := url.Values{} - // { username, ipaddr: clientIP, factor: "push", device: "auto", pushinfo: `target%20url=${targetURL}`} + values.Set("username", userSession.Username) values.Set("ipaddr", remoteIP) values.Set("factor", "push") @@ -37,7 +40,10 @@ func SecondFactorDuoPost(duoAPI duo.API) middlewares.RequestHandler { duoResponse, err := duoAPI.Call(values, ctx) if err != nil { - handleAuthenticationUnauthorized(ctx, fmt.Errorf("Duo API errored: %s", err), messageMFAValidationFailed) + ctx.Logger.Errorf("Failed to perform DUO call for user '%s': %+v", userSession.Username, err) + + respondUnauthorized(ctx, messageMFAValidationFailed) + return } @@ -53,14 +59,25 @@ func SecondFactorDuoPost(duoAPI duo.API) middlewares.RequestHandler { } if duoResponse.Response.Result != testResultAllow { - ctx.ReplyUnauthorized() + _ = markAuthenticationAttempt(ctx, false, nil, userSession.Username, regulation.AuthTypeDUO, + fmt.Errorf("result: %s, code: %d, message: %s (%s)", duoResponse.Response.Result, duoResponse.Code, + duoResponse.Message, duoResponse.MessageDetail)) + + respondUnauthorized(ctx, messageMFAValidationFailed) + return } - err = ctx.Providers.SessionProvider.RegenerateSession(ctx.RequestCtx) + if err = markAuthenticationAttempt(ctx, true, nil, userSession.Username, regulation.AuthTypeDUO, nil); err != nil { + respondUnauthorized(ctx, messageMFAValidationFailed) + return + } + + if err = ctx.Providers.SessionProvider.RegenerateSession(ctx.RequestCtx); err != nil { + ctx.Logger.Errorf(logFmtErrSessionRegenerate, regulation.AuthTypeDUO, userSession.Username, err) + + respondUnauthorized(ctx, messageMFAValidationFailed) - if err != nil { - handleAuthenticationUnauthorized(ctx, fmt.Errorf("unable to regenerate session for user %s: %s", userSession.Username, err), messageMFAValidationFailed) return } @@ -68,7 +85,10 @@ func SecondFactorDuoPost(duoAPI duo.API) middlewares.RequestHandler { err = ctx.SaveSession(userSession) if err != nil { - handleAuthenticationUnauthorized(ctx, fmt.Errorf("unable to update authentication level with Duo: %s", err), messageMFAValidationFailed) + ctx.Logger.Errorf(logFmtErrSessionSave, "authentication time", regulation.AuthTypeTOTP, userSession.Username, err) + + respondUnauthorized(ctx, messageMFAValidationFailed) + return } diff --git a/internal/handlers/handler_sign_duo_test.go b/internal/handlers/handler_sign_duo_test.go index cd7d0a4bb..239b557d6 100644 --- a/internal/handlers/handler_sign_duo_test.go +++ b/internal/handlers/handler_sign_duo_test.go @@ -14,6 +14,8 @@ import ( "github.com/authelia/authelia/v4/internal/duo" "github.com/authelia/authelia/v4/internal/mocks" + "github.com/authelia/authelia/v4/internal/models" + "github.com/authelia/authelia/v4/internal/regulation" ) type SecondFactorDuoPostSuite struct { @@ -47,6 +49,17 @@ func (s *SecondFactorDuoPostSuite) TestShouldCallDuoAPIAndAllowAccess() { response := duo.Response{} response.Response.Result = testResultAllow + s.mock.StorageProviderMock. + EXPECT(). + AppendAuthenticationLog(s.mock.Ctx, gomock.Eq(models.AuthenticationAttempt{ + Username: "john", + Successful: true, + Banned: false, + Time: s.mock.Clock.Now(), + Type: regulation.AuthTypeDUO, + RemoteIP: models.NewIPAddressFromString("0.0.0.0"), + })) + duoMock.EXPECT().Call(gomock.Eq(values), s.mock.Ctx).Return(&response, nil) s.mock.Ctx.Request.SetBodyString("{\"targetURL\": \"https://target.example.com\"}") @@ -69,6 +82,17 @@ func (s *SecondFactorDuoPostSuite) TestShouldCallDuoAPIAndDenyAccess() { response := duo.Response{} response.Response.Result = "deny" + s.mock.StorageProviderMock. + EXPECT(). + AppendAuthenticationLog(s.mock.Ctx, gomock.Eq(models.AuthenticationAttempt{ + Username: "john", + Successful: false, + Banned: false, + Time: s.mock.Clock.Now(), + Type: regulation.AuthTypeDUO, + RemoteIP: models.NewIPAddressFromString("0.0.0.0"), + })) + duoMock.EXPECT().Call(gomock.Eq(values), s.mock.Ctx).Return(&response, nil) s.mock.Ctx.Request.SetBodyString("{\"targetURL\": \"https://target.example.com\"}") @@ -88,7 +112,7 @@ func (s *SecondFactorDuoPostSuite) TestShouldCallDuoAPIAndFail() { values.Set("device", "auto") values.Set("pushinfo", "target%20url=https://target.example.com") - duoMock.EXPECT().Call(gomock.Eq(values), s.mock.Ctx).Return(nil, fmt.Errorf("Connnection error")) + duoMock.EXPECT().Call(gomock.Eq(values), s.mock.Ctx).Return(nil, fmt.Errorf("connnection error")) s.mock.Ctx.Request.SetBodyString("{\"targetURL\": \"https://target.example.com\"}") @@ -105,6 +129,17 @@ func (s *SecondFactorDuoPostSuite) TestShouldRedirectUserToDefaultURL() { duoMock.EXPECT().Call(gomock.Any(), s.mock.Ctx).Return(&response, nil) + s.mock.StorageProviderMock. + EXPECT(). + AppendAuthenticationLog(s.mock.Ctx, gomock.Eq(models.AuthenticationAttempt{ + Username: "john", + Successful: true, + Banned: false, + Time: s.mock.Clock.Now(), + Type: regulation.AuthTypeDUO, + RemoteIP: models.NewIPAddressFromString("0.0.0.0"), + })) + s.mock.Ctx.Configuration.DefaultRedirectionURL = testRedirectionURL bodyBytes, err := json.Marshal(signDuoRequestBody{}) @@ -125,6 +160,17 @@ func (s *SecondFactorDuoPostSuite) TestShouldNotReturnRedirectURL() { duoMock.EXPECT().Call(gomock.Any(), s.mock.Ctx).Return(&response, nil) + s.mock.StorageProviderMock. + EXPECT(). + AppendAuthenticationLog(s.mock.Ctx, gomock.Eq(models.AuthenticationAttempt{ + Username: "john", + Successful: true, + Banned: false, + Time: s.mock.Clock.Now(), + Type: regulation.AuthTypeDUO, + RemoteIP: models.NewIPAddressFromString("0.0.0.0"), + })) + bodyBytes, err := json.Marshal(signDuoRequestBody{}) s.Require().NoError(err) s.mock.Ctx.Request.SetBody(bodyBytes) @@ -141,6 +187,17 @@ func (s *SecondFactorDuoPostSuite) TestShouldRedirectUserToSafeTargetURL() { duoMock.EXPECT().Call(gomock.Any(), s.mock.Ctx).Return(&response, nil) + s.mock.StorageProviderMock. + EXPECT(). + AppendAuthenticationLog(s.mock.Ctx, gomock.Eq(models.AuthenticationAttempt{ + Username: "john", + Successful: true, + Banned: false, + Time: s.mock.Clock.Now(), + Type: regulation.AuthTypeDUO, + RemoteIP: models.NewIPAddressFromString("0.0.0.0"), + })) + bodyBytes, err := json.Marshal(signDuoRequestBody{ TargetURL: "https://mydomain.local", }) @@ -161,6 +218,17 @@ func (s *SecondFactorDuoPostSuite) TestShouldNotRedirectToUnsafeURL() { duoMock.EXPECT().Call(gomock.Any(), s.mock.Ctx).Return(&response, nil) + s.mock.StorageProviderMock. + EXPECT(). + AppendAuthenticationLog(s.mock.Ctx, gomock.Eq(models.AuthenticationAttempt{ + Username: "john", + Successful: true, + Banned: false, + Time: s.mock.Clock.Now(), + Type: regulation.AuthTypeDUO, + RemoteIP: models.NewIPAddressFromString("0.0.0.0"), + })) + bodyBytes, err := json.Marshal(signDuoRequestBody{ TargetURL: "http://mydomain.local", }) @@ -179,6 +247,17 @@ func (s *SecondFactorDuoPostSuite) TestShouldRegenerateSessionForPreventingSessi duoMock.EXPECT().Call(gomock.Any(), s.mock.Ctx).Return(&response, nil) + s.mock.StorageProviderMock. + EXPECT(). + AppendAuthenticationLog(s.mock.Ctx, gomock.Eq(models.AuthenticationAttempt{ + Username: "john", + Successful: true, + Banned: false, + Time: s.mock.Clock.Now(), + Type: regulation.AuthTypeDUO, + RemoteIP: models.NewIPAddressFromString("0.0.0.0"), + })) + bodyBytes, err := json.Marshal(signDuoRequestBody{ TargetURL: "http://mydomain.local", }) diff --git a/internal/handlers/handler_sign_totp.go b/internal/handlers/handler_sign_totp.go index 71c66879a..31ce766ec 100644 --- a/internal/handlers/handler_sign_totp.go +++ b/internal/handlers/handler_sign_totp.go @@ -1,19 +1,20 @@ package handlers import ( - "fmt" - "github.com/authelia/authelia/v4/internal/middlewares" + "github.com/authelia/authelia/v4/internal/regulation" ) // SecondFactorTOTPPost validate the TOTP passcode provided by the user. func SecondFactorTOTPPost(totpVerifier TOTPVerifier) middlewares.RequestHandler { return func(ctx *middlewares.AutheliaCtx) { requestBody := signTOTPRequestBody{} - err := ctx.ParseBody(&requestBody) - if err != nil { - handleAuthenticationUnauthorized(ctx, err, messageMFAValidationFailed) + if err := ctx.ParseBody(&requestBody); err != nil { + ctx.Logger.Errorf(logFmtErrParseRequestBody, regulation.AuthTypeTOTP, err) + + respondUnauthorized(ctx, messageMFAValidationFailed) + return } @@ -21,33 +22,50 @@ func SecondFactorTOTPPost(totpVerifier TOTPVerifier) middlewares.RequestHandler config, err := ctx.Providers.StorageProvider.LoadTOTPConfiguration(ctx, userSession.Username) if err != nil { - handleAuthenticationUnauthorized(ctx, fmt.Errorf("unable to load TOTP secret: %s", err), messageMFAValidationFailed) + ctx.Logger.Errorf("Failed to load TOTP configuration: %+v", err) + + respondUnauthorized(ctx, messageMFAValidationFailed) + return } isValid, err := totpVerifier.Verify(config, requestBody.Token) if err != nil { - handleAuthenticationUnauthorized(ctx, fmt.Errorf("error occurred during OTP validation for user %s: %s", userSession.Username, err), messageMFAValidationFailed) + ctx.Logger.Errorf("Failed to perform TOTP verification: %+v", err) + + respondUnauthorized(ctx, messageMFAValidationFailed) + return } if !isValid { - handleAuthenticationUnauthorized(ctx, fmt.Errorf("wrong passcode during TOTP validation for user %s", userSession.Username), messageMFAValidationFailed) + _ = markAuthenticationAttempt(ctx, false, nil, userSession.Username, regulation.AuthTypeTOTP, nil) + + respondUnauthorized(ctx, messageMFAValidationFailed) + return } - err = ctx.Providers.SessionProvider.RegenerateSession(ctx.RequestCtx) + if err = markAuthenticationAttempt(ctx, true, nil, userSession.Username, regulation.AuthTypeTOTP, nil); err != nil { + respondUnauthorized(ctx, messageMFAValidationFailed) + return + } + + if err = ctx.Providers.SessionProvider.RegenerateSession(ctx.RequestCtx); err != nil { + ctx.Logger.Errorf(logFmtErrSessionRegenerate, regulation.AuthTypeTOTP, userSession.Username, err) + + respondUnauthorized(ctx, messageMFAValidationFailed) - if err != nil { - handleAuthenticationUnauthorized(ctx, fmt.Errorf("unable to regenerate session for user %s: %s", userSession.Username, err), messageMFAValidationFailed) return } userSession.SetTwoFactor(ctx.Clock.Now()) - err = ctx.SaveSession(userSession) - if err != nil { - handleAuthenticationUnauthorized(ctx, fmt.Errorf("unable to update the authentication level with TOTP: %s", err), messageMFAValidationFailed) + if err = ctx.SaveSession(userSession); err != nil { + ctx.Logger.Errorf(logFmtErrSessionSave, "authentication time", regulation.AuthTypeTOTP, userSession.Username, err) + + respondUnauthorized(ctx, messageMFAValidationFailed) + return } diff --git a/internal/handlers/handler_sign_totp_test.go b/internal/handlers/handler_sign_totp_test.go index 7867e606d..af5b4b479 100644 --- a/internal/handlers/handler_sign_totp_test.go +++ b/internal/handlers/handler_sign_totp_test.go @@ -12,6 +12,7 @@ import ( "github.com/authelia/authelia/v4/internal/mocks" "github.com/authelia/authelia/v4/internal/models" + "github.com/authelia/authelia/v4/internal/regulation" "github.com/authelia/authelia/v4/internal/session" ) @@ -44,6 +45,17 @@ func (s *HandlerSignTOTPSuite) TestShouldRedirectUserToDefaultURL() { LoadTOTPConfiguration(s.mock.Ctx, gomock.Any()). Return(&config, nil) + s.mock.StorageProviderMock. + EXPECT(). + AppendAuthenticationLog(s.mock.Ctx, gomock.Eq(models.AuthenticationAttempt{ + Username: "john", + Successful: true, + Banned: false, + Time: s.mock.Clock.Now(), + Type: regulation.AuthTypeTOTP, + RemoteIP: models.NewIPAddressFromString("0.0.0.0"), + })) + verifier.EXPECT(). Verify(gomock.Eq(&config), gomock.Eq("abc")). Return(true, nil) @@ -71,6 +83,17 @@ func (s *HandlerSignTOTPSuite) TestShouldNotReturnRedirectURL() { LoadTOTPConfiguration(s.mock.Ctx, gomock.Any()). Return(&config, nil) + s.mock.StorageProviderMock. + EXPECT(). + AppendAuthenticationLog(s.mock.Ctx, gomock.Eq(models.AuthenticationAttempt{ + Username: "john", + Successful: true, + Banned: false, + Time: s.mock.Clock.Now(), + Type: regulation.AuthTypeTOTP, + RemoteIP: models.NewIPAddressFromString("0.0.0.0"), + })) + verifier.EXPECT(). Verify(gomock.Eq(&config), gomock.Eq("abc")). Return(true, nil) @@ -94,6 +117,17 @@ func (s *HandlerSignTOTPSuite) TestShouldRedirectUserToSafeTargetURL() { LoadTOTPConfiguration(s.mock.Ctx, gomock.Any()). Return(&config, nil) + s.mock.StorageProviderMock. + EXPECT(). + AppendAuthenticationLog(s.mock.Ctx, gomock.Eq(models.AuthenticationAttempt{ + Username: "john", + Successful: true, + Banned: false, + Time: s.mock.Clock.Now(), + Type: regulation.AuthTypeTOTP, + RemoteIP: models.NewIPAddressFromString("0.0.0.0"), + })) + verifier.EXPECT(). Verify(gomock.Eq(&config), gomock.Eq("abc")). Return(true, nil) @@ -118,6 +152,17 @@ func (s *HandlerSignTOTPSuite) TestShouldNotRedirectToUnsafeURL() { LoadTOTPConfiguration(s.mock.Ctx, gomock.Any()). Return(&models.TOTPConfiguration{Secret: []byte("secret")}, nil) + s.mock.StorageProviderMock. + EXPECT(). + AppendAuthenticationLog(s.mock.Ctx, gomock.Eq(models.AuthenticationAttempt{ + Username: "john", + Successful: true, + Banned: false, + Time: s.mock.Clock.Now(), + Type: regulation.AuthTypeTOTP, + RemoteIP: models.NewIPAddressFromString("0.0.0.0"), + })) + verifier.EXPECT(). Verify(gomock.Eq(&models.TOTPConfiguration{Secret: []byte("secret")}), gomock.Eq("abc")). Return(true, nil) @@ -142,6 +187,17 @@ func (s *HandlerSignTOTPSuite) TestShouldRegenerateSessionForPreventingSessionFi LoadTOTPConfiguration(s.mock.Ctx, gomock.Any()). Return(&config, nil) + s.mock.StorageProviderMock. + EXPECT(). + AppendAuthenticationLog(s.mock.Ctx, gomock.Eq(models.AuthenticationAttempt{ + Username: "john", + Successful: true, + Banned: false, + Time: s.mock.Clock.Now(), + Type: regulation.AuthTypeTOTP, + RemoteIP: models.NewIPAddressFromString("0.0.0.0"), + })) + verifier.EXPECT(). Verify(gomock.Eq(&config), gomock.Eq("abc")). Return(true, nil) diff --git a/internal/handlers/handler_sign_u2f_step1.go b/internal/handlers/handler_sign_u2f_step1.go index 613d2372c..dec999016 100644 --- a/internal/handlers/handler_sign_u2f_step1.go +++ b/internal/handlers/handler_sign_u2f_step1.go @@ -1,12 +1,14 @@ package handlers import ( + "crypto/ecdsa" "crypto/elliptic" "fmt" "github.com/tstranex/u2f" "github.com/authelia/authelia/v4/internal/middlewares" + "github.com/authelia/authelia/v4/internal/regulation" "github.com/authelia/authelia/v4/internal/session" "github.com/authelia/authelia/v4/internal/storage" ) @@ -23,55 +25,69 @@ func SecondFactorU2FSignGet(ctx *middlewares.AutheliaCtx) { return } + userSession := ctx.GetSession() + appID := fmt.Sprintf("%s://%s", ctx.XForwardedProto(), ctx.XForwardedHost()) var trustedFacets = []string{appID} - challenge, err := u2f.NewChallenge(appID, trustedFacets) + challenge, err := u2f.NewChallenge(appID, trustedFacets) if err != nil { - handleAuthenticationUnauthorized(ctx, fmt.Errorf("unable to create U2F challenge: %s", err), messageMFAValidationFailed) + ctx.Logger.Errorf("Unable to create %s challenge for user '%s': %+v", regulation.AuthTypeFIDO, userSession.Username, err) + + respondUnauthorized(ctx, messageMFAValidationFailed) + return } - userSession := ctx.GetSession() device, err := ctx.Providers.StorageProvider.LoadU2FDevice(ctx, userSession.Username) - if err != nil { + respondUnauthorized(ctx, messageMFAValidationFailed) + if err == storage.ErrNoU2FDeviceHandle { - handleAuthenticationUnauthorized(ctx, fmt.Errorf("no device handle found for user %s", userSession.Username), messageMFAValidationFailed) + _ = markAuthenticationAttempt(ctx, false, nil, userSession.Username, regulation.AuthTypeFIDO, fmt.Errorf("no registered U2F device")) return } - handleAuthenticationUnauthorized(ctx, fmt.Errorf("unable to retrieve U2F device handle: %s", err), messageMFAValidationFailed) + ctx.Logger.Errorf("Could not load %s devices for user '%s': %+v", regulation.AuthTypeFIDO, userSession.Username, err) return } - var registration u2f.Registration - registration.KeyHandle = device.KeyHandle x, y := elliptic.Unmarshal(elliptic.P256(), device.PublicKey) - registration.PubKey.Curve = elliptic.P256() - registration.PubKey.X = x - registration.PubKey.Y = y + + registration := u2f.Registration{ + KeyHandle: device.KeyHandle, + PubKey: ecdsa.PublicKey{ + Curve: elliptic.P256(), + X: x, + Y: y, + }, + } // Save the challenge and registration for use in next request userSession.U2FRegistration = &session.U2FRegistration{ KeyHandle: device.KeyHandle, PublicKey: device.PublicKey, } - userSession.U2FChallenge = challenge - err = ctx.SaveSession(userSession) - if err != nil { - handleAuthenticationUnauthorized(ctx, fmt.Errorf("unable to save U2F challenge and registration in session: %s", err), messageMFAValidationFailed) + userSession.U2FChallenge = challenge + + if err = ctx.SaveSession(userSession); err != nil { + ctx.Logger.Errorf(logFmtErrSessionSave, "challenge and registration", regulation.AuthTypeFIDO, userSession.Username, err) + + respondUnauthorized(ctx, messageMFAValidationFailed) + return } signRequest := challenge.SignRequest([]u2f.Registration{registration}) - err = ctx.SetJSONBody(signRequest) - if err != nil { - handleAuthenticationUnauthorized(ctx, fmt.Errorf("unable to set sign request in body: %s", err), messageMFAValidationFailed) + if err = ctx.SetJSONBody(signRequest); err != nil { + ctx.Logger.Errorf(logFmtErrWriteResponseBody, regulation.AuthTypeFIDO, userSession.Username, err) + + respondUnauthorized(ctx, messageMFAValidationFailed) + return } } diff --git a/internal/handlers/handler_sign_u2f_step2.go b/internal/handlers/handler_sign_u2f_step2.go index 85c4a5207..c0e28f952 100644 --- a/internal/handlers/handler_sign_u2f_step2.go +++ b/internal/handlers/handler_sign_u2f_step2.go @@ -1,48 +1,64 @@ package handlers import ( - "fmt" + "errors" "github.com/authelia/authelia/v4/internal/middlewares" + "github.com/authelia/authelia/v4/internal/regulation" ) // SecondFactorU2FSignPost handler for completing a signing request. func SecondFactorU2FSignPost(u2fVerifier U2FVerifier) middlewares.RequestHandler { return func(ctx *middlewares.AutheliaCtx) { - var requestBody signU2FRequestBody - err := ctx.ParseBody(&requestBody) + var ( + requestBody signU2FRequestBody + err error + ) + + if err := ctx.ParseBody(&requestBody); err != nil { + ctx.Logger.Errorf(logFmtErrParseRequestBody, regulation.AuthTypeFIDO, err) + + respondUnauthorized(ctx, messageMFAValidationFailed) - if err != nil { - ctx.Error(err, messageMFAValidationFailed) return } userSession := ctx.GetSession() if userSession.U2FChallenge == nil { - handleAuthenticationUnauthorized(ctx, fmt.Errorf("U2F signing has not been initiated yet (no challenge)"), messageMFAValidationFailed) + _ = markAuthenticationAttempt(ctx, false, nil, userSession.Username, regulation.AuthTypeFIDO, errors.New("session did not contain a challenge")) + + respondUnauthorized(ctx, messageMFAValidationFailed) + return } if userSession.U2FRegistration == nil { - handleAuthenticationUnauthorized(ctx, fmt.Errorf("U2F signing has not been initiated yet (no registration)"), messageMFAValidationFailed) + _ = markAuthenticationAttempt(ctx, false, nil, userSession.Username, regulation.AuthTypeFIDO, errors.New("session did not contain a registration")) + + respondUnauthorized(ctx, messageMFAValidationFailed) + return } - err = u2fVerifier.Verify( - userSession.U2FRegistration.KeyHandle, - userSession.U2FRegistration.PublicKey, - requestBody.SignResponse, - *userSession.U2FChallenge) + if err = u2fVerifier.Verify(userSession.U2FRegistration.KeyHandle, userSession.U2FRegistration.PublicKey, + requestBody.SignResponse, *userSession.U2FChallenge); err != nil { + _ = markAuthenticationAttempt(ctx, false, nil, userSession.Username, regulation.AuthTypeFIDO, err) + + respondUnauthorized(ctx, messageMFAValidationFailed) - if err != nil { - ctx.Error(err, messageMFAValidationFailed) return } - err = ctx.Providers.SessionProvider.RegenerateSession(ctx.RequestCtx) + if err = ctx.Providers.SessionProvider.RegenerateSession(ctx.RequestCtx); err != nil { + ctx.Logger.Errorf(logFmtErrSessionRegenerate, regulation.AuthTypeFIDO, userSession.Username, err) - if err != nil { - handleAuthenticationUnauthorized(ctx, fmt.Errorf("unable to regenerate session for user %s: %s", userSession.Username, err), messageMFAValidationFailed) + respondUnauthorized(ctx, messageMFAValidationFailed) + + return + } + + if err = markAuthenticationAttempt(ctx, true, nil, userSession.Username, regulation.AuthTypeFIDO, nil); err != nil { + respondUnauthorized(ctx, messageMFAValidationFailed) return } @@ -50,7 +66,10 @@ func SecondFactorU2FSignPost(u2fVerifier U2FVerifier) middlewares.RequestHandler err = ctx.SaveSession(userSession) if err != nil { - handleAuthenticationUnauthorized(ctx, fmt.Errorf("unable to update authentication level with U2F: %s", err), messageMFAValidationFailed) + ctx.Logger.Errorf(logFmtErrSessionSave, "authentication time", regulation.AuthTypeFIDO, userSession.Username, err) + + respondUnauthorized(ctx, messageMFAValidationFailed) + return } diff --git a/internal/handlers/handler_sign_u2f_step2_test.go b/internal/handlers/handler_sign_u2f_step2_test.go index 7ef81fb8a..e921c113b 100644 --- a/internal/handlers/handler_sign_u2f_step2_test.go +++ b/internal/handlers/handler_sign_u2f_step2_test.go @@ -11,6 +11,8 @@ import ( "github.com/tstranex/u2f" "github.com/authelia/authelia/v4/internal/mocks" + "github.com/authelia/authelia/v4/internal/models" + "github.com/authelia/authelia/v4/internal/regulation" "github.com/authelia/authelia/v4/internal/session" ) @@ -41,6 +43,17 @@ func (s *HandlerSignU2FStep2Suite) TestShouldRedirectUserToDefaultURL() { Verify(gomock.Any(), gomock.Any(), gomock.Any(), gomock.Any()). Return(nil) + s.mock.StorageProviderMock. + EXPECT(). + AppendAuthenticationLog(s.mock.Ctx, gomock.Eq(models.AuthenticationAttempt{ + Username: "john", + Successful: true, + Banned: false, + Time: s.mock.Clock.Now(), + Type: regulation.AuthTypeFIDO, + RemoteIP: models.NewIPAddressFromString("0.0.0.0"), + })) + s.mock.Ctx.Configuration.DefaultRedirectionURL = testRedirectionURL bodyBytes, err := json.Marshal(signU2FRequestBody{ @@ -62,6 +75,17 @@ func (s *HandlerSignU2FStep2Suite) TestShouldNotReturnRedirectURL() { Verify(gomock.Any(), gomock.Any(), gomock.Any(), gomock.Any()). Return(nil) + s.mock.StorageProviderMock. + EXPECT(). + AppendAuthenticationLog(s.mock.Ctx, gomock.Eq(models.AuthenticationAttempt{ + Username: "john", + Successful: true, + Banned: false, + Time: s.mock.Clock.Now(), + Type: regulation.AuthTypeFIDO, + RemoteIP: models.NewIPAddressFromString("0.0.0.0"), + })) + bodyBytes, err := json.Marshal(signU2FRequestBody{ SignResponse: u2f.SignResponse{}, }) @@ -79,6 +103,17 @@ func (s *HandlerSignU2FStep2Suite) TestShouldRedirectUserToSafeTargetURL() { Verify(gomock.Any(), gomock.Any(), gomock.Any(), gomock.Any()). Return(nil) + s.mock.StorageProviderMock. + EXPECT(). + AppendAuthenticationLog(s.mock.Ctx, gomock.Eq(models.AuthenticationAttempt{ + Username: "john", + Successful: true, + Banned: false, + Time: s.mock.Clock.Now(), + Type: regulation.AuthTypeFIDO, + RemoteIP: models.NewIPAddressFromString("0.0.0.0"), + })) + bodyBytes, err := json.Marshal(signU2FRequestBody{ SignResponse: u2f.SignResponse{}, TargetURL: "https://mydomain.local", @@ -99,6 +134,17 @@ func (s *HandlerSignU2FStep2Suite) TestShouldNotRedirectToUnsafeURL() { Verify(gomock.Any(), gomock.Any(), gomock.Any(), gomock.Any()). Return(nil) + s.mock.StorageProviderMock. + EXPECT(). + AppendAuthenticationLog(s.mock.Ctx, gomock.Eq(models.AuthenticationAttempt{ + Username: "john", + Successful: true, + Banned: false, + Time: s.mock.Clock.Now(), + Type: regulation.AuthTypeFIDO, + RemoteIP: models.NewIPAddressFromString("0.0.0.0"), + })) + bodyBytes, err := json.Marshal(signU2FRequestBody{ SignResponse: u2f.SignResponse{}, TargetURL: "http://mydomain.local", @@ -117,6 +163,17 @@ func (s *HandlerSignU2FStep2Suite) TestShouldRegenerateSessionForPreventingSessi Verify(gomock.Any(), gomock.Any(), gomock.Any(), gomock.Any()). Return(nil) + s.mock.StorageProviderMock. + EXPECT(). + AppendAuthenticationLog(s.mock.Ctx, gomock.Eq(models.AuthenticationAttempt{ + Username: "john", + Successful: true, + Banned: false, + Time: s.mock.Clock.Now(), + Type: regulation.AuthTypeFIDO, + RemoteIP: models.NewIPAddressFromString("0.0.0.0"), + })) + bodyBytes, err := json.Marshal(signU2FRequestBody{ SignResponse: u2f.SignResponse{}, }) diff --git a/internal/handlers/handler_user_info_test.go b/internal/handlers/handler_user_info_test.go index f64d36d34..c062f3f35 100644 --- a/internal/handlers/handler_user_info_test.go +++ b/internal/handlers/handler_user_info_test.go @@ -178,7 +178,7 @@ func (s *SaveSuite) TestShouldReturnError500WhenNoBodyProvided() { MethodPreferencePost(s.mock.Ctx) s.mock.Assert200KO(s.T(), "Operation failed.") - assert.Equal(s.T(), "Unable to parse body: unexpected end of JSON input", s.mock.Hook.LastEntry().Message) + assert.Equal(s.T(), "unable to parse body: unexpected end of JSON input", s.mock.Hook.LastEntry().Message) assert.Equal(s.T(), logrus.ErrorLevel, s.mock.Hook.LastEntry().Level) } @@ -187,7 +187,7 @@ func (s *SaveSuite) TestShouldReturnError500WhenMalformedBodyProvided() { MethodPreferencePost(s.mock.Ctx) s.mock.Assert200KO(s.T(), "Operation failed.") - assert.Equal(s.T(), "Unable to parse body: unexpected end of JSON input", s.mock.Hook.LastEntry().Message) + assert.Equal(s.T(), "unable to parse body: unexpected end of JSON input", s.mock.Hook.LastEntry().Message) assert.Equal(s.T(), logrus.ErrorLevel, s.mock.Hook.LastEntry().Level) } @@ -196,7 +196,7 @@ func (s *SaveSuite) TestShouldReturnError500WhenBadBodyProvided() { MethodPreferencePost(s.mock.Ctx) s.mock.Assert200KO(s.T(), "Operation failed.") - assert.Equal(s.T(), "Unable to validate body: method: non zero value required", s.mock.Hook.LastEntry().Message) + assert.Equal(s.T(), "unable to validate body: method: non zero value required", s.mock.Hook.LastEntry().Message) assert.Equal(s.T(), logrus.ErrorLevel, s.mock.Hook.LastEntry().Level) } diff --git a/internal/handlers/response.go b/internal/handlers/response.go index c86808a79..34a26860f 100644 --- a/internal/handlers/response.go +++ b/internal/handlers/response.go @@ -3,6 +3,7 @@ package handlers import ( "fmt" "net/url" + "time" "github.com/valyala/fasthttp" @@ -24,8 +25,9 @@ func handleOIDCWorkflowResponse(ctx *middlewares.AutheliaCtx) { uri, err := ctx.ExternalRootURL() if err != nil { - ctx.Logger.Errorf("Unable to extract external root URL: %v", err) - handleAuthenticationUnauthorized(ctx, fmt.Errorf("unable to get forward facing URI"), messageAuthenticationFailed) + ctx.Logger.Errorf("Unable to determine external Base URL: %v", err) + + respondUnauthorized(ctx, messageOperationFailed) return } @@ -144,8 +146,33 @@ func Handle2FAResponse(ctx *middlewares.AutheliaCtx, targetURI string) { } } -// handleAuthenticationUnauthorized provides harmonized response codes for 1FA. -func handleAuthenticationUnauthorized(ctx *middlewares.AutheliaCtx, err error, message string) { - ctx.SetStatusCode(fasthttp.StatusUnauthorized) - ctx.Error(err, message) +func markAuthenticationAttempt(ctx *middlewares.AutheliaCtx, successful bool, bannedUntil *time.Time, username string, authType string, errAuth error) (err error) { + // We only Mark if there was no underlying error. + ctx.Logger.Debugf("Mark %s authentication attempt made by user '%s'", authType, username) + + if err = ctx.Providers.Regulator.Mark(ctx, successful, bannedUntil != nil, username, string(ctx.RequestCtx.QueryArgs().Peek("rd")), string(ctx.RequestCtx.QueryArgs().Peek("rm")), authType, ctx.RemoteIP()); err != nil { + ctx.Logger.Errorf("Unable to mark %s authentication attempt by user '%s': %+v", authType, username, err) + + return err + } + + if successful { + ctx.Logger.Debugf("Successful %s authentication attempt made by user '%s'", authType, username) + } else { + switch { + case errAuth != nil: + ctx.Logger.Errorf("Unsuccessful %s authentication attempt by user '%s': %+v", authType, username, errAuth) + case bannedUntil != nil: + ctx.Logger.Errorf("Unsuccessful %s authentication attempt by user '%s' and they are banned until %s", authType, username, bannedUntil) + default: + ctx.Logger.Errorf("Unsuccessful %s authentication attempt by user '%s'", authType, username) + } + } + + return nil +} + +func respondUnauthorized(ctx *middlewares.AutheliaCtx, message string) { + ctx.SetStatusCode(fasthttp.StatusUnauthorized) + ctx.SetJSONError(message) } diff --git a/internal/middlewares/authelia_context.go b/internal/middlewares/authelia_context.go index 1d5af2968..4a1242cab 100644 --- a/internal/middlewares/authelia_context.go +++ b/internal/middlewares/authelia_context.go @@ -55,6 +55,13 @@ func AutheliaMiddleware(configuration schema.Configuration, providers Providers) // Error reply with an error and display the stack trace in the logs. func (c *AutheliaCtx) Error(err error, message string) { + c.SetJSONError(message) + + c.Logger.Error(err) +} + +// SetJSONError sets the body of the response to an JSON error KO message. +func (c *AutheliaCtx) SetJSONError(message string) { b, marshalErr := json.Marshal(ErrorResponse{Status: "KO", Message: message}) if marshalErr != nil { @@ -63,7 +70,6 @@ func (c *AutheliaCtx) Error(err error, message string) { c.SetContentType(contentTypeApplicationJSON) c.SetBody(b) - c.Logger.Error(err) } // ReplyError reply with an error but does not display any stack trace in the logs. @@ -183,13 +189,13 @@ func (c *AutheliaCtx) ParseBody(value interface{}) error { err := json.Unmarshal(c.PostBody(), &value) if err != nil { - return fmt.Errorf("Unable to parse body: %s", err) + return fmt.Errorf("unable to parse body: %w", err) } valid, err := govalidator.ValidateStruct(value) if err != nil { - return fmt.Errorf("Unable to validate body: %s", err) + return fmt.Errorf("unable to validate body: %w", err) } if !valid { @@ -203,7 +209,7 @@ func (c *AutheliaCtx) ParseBody(value interface{}) error { func (c *AutheliaCtx) SetJSONBody(value interface{}) error { b, err := json.Marshal(OKResponse{Status: "OK", Data: value}) if err != nil { - return fmt.Errorf("Unable to marshal JSON body") + return fmt.Errorf("unable to marshal JSON body: %w", err) } c.SetContentType(contentTypeApplicationJSON) diff --git a/internal/models/model_authentication_attempt.go b/internal/models/model_authentication_attempt.go index 6720b524c..01812812c 100644 --- a/internal/models/model_authentication_attempt.go +++ b/internal/models/model_authentication_attempt.go @@ -9,6 +9,7 @@ type AuthenticationAttempt struct { ID int `db:"id"` Time time.Time `db:"time"` Successful bool `db:"successful"` + Banned bool `db:"banned"` Username string `db:"username"` Type string `db:"auth_type"` RemoteIP IPAddress `db:"remote_ip"` diff --git a/internal/models/type_ipaddress.go b/internal/models/type_ipaddress.go index 8078748bd..09c529f2a 100644 --- a/internal/models/type_ipaddress.go +++ b/internal/models/type_ipaddress.go @@ -6,6 +6,12 @@ import ( "net" ) +// NewIPAddressFromString converts a string into an IPAddress. +func NewIPAddressFromString(ip string) (ipAddress IPAddress) { + actualIP := net.ParseIP(ip) + return IPAddress{IP: &actualIP} +} + // IPAddress is a type specific for storage of a net.IP in the database. type IPAddress struct { *net.IP diff --git a/internal/regulation/const.go b/internal/regulation/const.go index 7260f2abb..f5c2e6041 100644 --- a/internal/regulation/const.go +++ b/internal/regulation/const.go @@ -4,3 +4,20 @@ import "fmt" // ErrUserIsBanned user is banned error message. var ErrUserIsBanned = fmt.Errorf("user is banned") + +const ( + // AuthType1FA is the string representing an auth log for first-factor authentication. + AuthType1FA = "1FA" + + // AuthTypeTOTP is the string representing an auth log for second-factor authentication via TOTP. + AuthTypeTOTP = "TOTP" + + // AuthTypeFIDO is the string representing an auth log for second-factor authentication via FIDO/CTAP1/U2F. + AuthTypeFIDO = "FIDO" + + // AuthTypeFIDO2 is the string representing an auth log for second-factor authentication via FIDO2/CTAP2/Webauthn. + // TODO: Add FIDO2. + + // AuthTypeDUO is the string representing an auth log for second-factor authentication via DUO. + AuthTypeDUO = "DUO" +) diff --git a/internal/regulation/regulator.go b/internal/regulation/regulator.go index f4b89870a..5b59081ba 100644 --- a/internal/regulation/regulator.go +++ b/internal/regulation/regulator.go @@ -3,6 +3,7 @@ package regulation import ( "context" "fmt" + "net" "time" "github.com/authelia/authelia/v4/internal/configuration/schema" @@ -43,11 +44,16 @@ func NewRegulator(configuration *schema.RegulationConfiguration, provider storag // Mark an authentication attempt. // We split Mark and Regulate in order to avoid timing attacks. -func (r *Regulator) Mark(ctx context.Context, username string, successful bool) error { +func (r *Regulator) Mark(ctx context.Context, successful, banned bool, username, requestURI, requestMethod, authType string, remoteIP net.IP) error { return r.storageProvider.AppendAuthenticationLog(ctx, models.AuthenticationAttempt{ - Username: username, - Successful: successful, - Time: r.clock.Now(), + Time: r.clock.Now(), + Successful: successful, + Banned: banned, + Username: username, + Type: authType, + RemoteIP: models.IPAddress{IP: &remoteIP}, + RequestURI: requestURI, + RequestMethod: requestMethod, }) } diff --git a/internal/session/encrypting_serializer_test.go b/internal/session/encrypting_serializer_test.go index 463e14a5e..288c990ea 100644 --- a/internal/session/encrypting_serializer_test.go +++ b/internal/session/encrypting_serializer_test.go @@ -4,7 +4,6 @@ import ( "testing" "github.com/fasthttp/session/v2" - "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) diff --git a/internal/storage/migrations/V0001.Initial_Schema.mysql.up.sql b/internal/storage/migrations/V0001.Initial_Schema.mysql.up.sql index e7b1ca848..98cb08c55 100644 --- a/internal/storage/migrations/V0001.Initial_Schema.mysql.up.sql +++ b/internal/storage/migrations/V0001.Initial_Schema.mysql.up.sql @@ -1,12 +1,18 @@ CREATE TABLE IF NOT EXISTS authentication_logs ( id INTEGER AUTO_INCREMENT, time TIMESTAMP NOT NULL DEFAULT CURRENT_TIMESTAMP, - successful BOOL NOT NULL, + successful BOOLEAN NOT NULL, + banned BOOLEAN NOT NULL DEFAULT FALSE, username VARCHAR(100) NOT NULL, + auth_type VARCHAR(5) NOT NULL DEFAULT '1FA', + remote_ip VARCHAR(47) NULL DEFAULT NULL, + request_uri TEXT NOT NULL, + request_method VARCHAR(4) NOT NULL DEFAULT '', PRIMARY KEY (id) ); -CREATE INDEX authentication_logs_username_idx ON authentication_logs (time, username); +CREATE INDEX authentication_logs_username_idx ON authentication_logs (time, username, auth_type); +CREATE INDEX authentication_logs_remote_ip_idx ON authentication_logs (time, remote_ip, auth_type); CREATE TABLE IF NOT EXISTS identity_verification_tokens ( id INTEGER AUTO_INCREMENT, @@ -19,6 +25,7 @@ CREATE TABLE IF NOT EXISTS identity_verification_tokens ( CREATE TABLE IF NOT EXISTS totp_configurations ( id INTEGER AUTO_INCREMENT, username VARCHAR(100) NOT NULL, + issuer VARCHAR(100), algorithm VARCHAR(6) NOT NULL DEFAULT 'SHA1', digits INTEGER NOT NULL DEFAULT 6, totp_period INTEGER NOT NULL DEFAULT 30, diff --git a/internal/storage/migrations/V0001.Initial_Schema.postgres.up.sql b/internal/storage/migrations/V0001.Initial_Schema.postgres.up.sql index 467368de3..bef73a3f1 100644 --- a/internal/storage/migrations/V0001.Initial_Schema.postgres.up.sql +++ b/internal/storage/migrations/V0001.Initial_Schema.postgres.up.sql @@ -2,11 +2,17 @@ CREATE TABLE IF NOT EXISTS authentication_logs ( id SERIAL, time TIMESTAMP WITH TIME ZONE NOT NULL DEFAULT CURRENT_TIMESTAMP, successful BOOLEAN NOT NULL, + banned BOOLEAN NOT NULL DEFAULT FALSE, username VARCHAR(100) NOT NULL, + auth_type VARCHAR(5) NOT NULL DEFAULT '1FA', + remote_ip VARCHAR(47) NULL DEFAULT NULL, + request_uri TEXT, + request_method VARCHAR(4) NOT NULL DEFAULT '', PRIMARY KEY (id) ); -CREATE INDEX authentication_logs_username_idx ON authentication_logs (time, username); +CREATE INDEX authentication_logs_username_idx ON authentication_logs (time, username, auth_type); +CREATE INDEX authentication_logs_remote_ip_idx ON authentication_logs (time, remote_ip, auth_type); CREATE TABLE IF NOT EXISTS identity_verification_tokens ( id SERIAL, @@ -19,6 +25,7 @@ CREATE TABLE IF NOT EXISTS identity_verification_tokens ( CREATE TABLE IF NOT EXISTS totp_configurations ( id SERIAL, username VARCHAR(100) NOT NULL, + issuer VARCHAR(100), algorithm VARCHAR(6) NOT NULL DEFAULT 'SHA1', digits INTEGER NOT NULL DEFAULT 6, totp_period INTEGER NOT NULL DEFAULT 30, diff --git a/internal/storage/migrations/V0001.Initial_Schema.sqlite.up.sql b/internal/storage/migrations/V0001.Initial_Schema.sqlite.up.sql index 2a0b5e6bd..06b3303ed 100644 --- a/internal/storage/migrations/V0001.Initial_Schema.sqlite.up.sql +++ b/internal/storage/migrations/V0001.Initial_Schema.sqlite.up.sql @@ -2,11 +2,17 @@ CREATE TABLE IF NOT EXISTS authentication_logs ( id INTEGER, time TIMESTAMP NOT NULL DEFAULT CURRENT_TIMESTAMP, successful BOOLEAN NOT NULL, + banned BOOLEAN NOT NULL DEFAULT FALSE, username VARCHAR(100) NOT NULL, + auth_type VARCHAR(5) NOT NULL DEFAULT '1FA', + remote_ip VARCHAR(47) NULL DEFAULT NULL, + request_uri TEXT, + request_method VARCHAR(4) NOT NULL DEFAULT '', PRIMARY KEY (id) ); -CREATE INDEX authentication_logs_username_idx ON authentication_logs (time, username); +CREATE INDEX authentication_logs_username_idx ON authentication_logs (time, username, auth_type); +CREATE INDEX authentication_logs_remote_ip_idx ON authentication_logs (time, remote_ip, auth_type); CREATE TABLE IF NOT EXISTS identity_verification_tokens ( id INTEGER, @@ -19,8 +25,9 @@ CREATE TABLE IF NOT EXISTS identity_verification_tokens ( CREATE TABLE IF NOT EXISTS totp_configurations ( id INTEGER, username VARCHAR(100) NOT NULL, + issuer VARCHAR(100), algorithm VARCHAR(6) NOT NULL DEFAULT 'SHA1', - digits INTEGER(1) NOT NULL DEFAULT 6, + digits INTEGER NOT NULL DEFAULT 6, totp_period INTEGER NOT NULL DEFAULT 30, secret BLOB NOT NULL, PRIMARY KEY (id), diff --git a/internal/storage/sql_provider.go b/internal/storage/sql_provider.go index 9ff5dad2b..5b876f4cf 100644 --- a/internal/storage/sql_provider.go +++ b/internal/storage/sql_provider.go @@ -355,8 +355,10 @@ func (p *SQLProvider) LoadU2FDevice(ctx context.Context, username string) (devic // AppendAuthenticationLog append a mark to the authentication log. func (p *SQLProvider) AppendAuthenticationLog(ctx context.Context, attempt models.AuthenticationAttempt) (err error) { - if _, err = p.db.ExecContext(ctx, p.sqlInsertAuthenticationAttempt, attempt.Time, attempt.Successful, attempt.Username); err != nil { - return fmt.Errorf("error inserting authentiation attempt: %w", err) + if _, err = p.db.ExecContext(ctx, p.sqlInsertAuthenticationAttempt, + attempt.Time, attempt.Successful, attempt.Banned, attempt.Username, + attempt.Type, attempt.RemoteIP, attempt.RequestURI, attempt.RequestMethod); err != nil { + return fmt.Errorf("error inserting authentication attempt: %w", err) } return nil diff --git a/internal/storage/sql_provider_queries.go b/internal/storage/sql_provider_queries.go index 57c2f4687..a4cb5a1ce 100644 --- a/internal/storage/sql_provider_queries.go +++ b/internal/storage/sql_provider_queries.go @@ -130,13 +130,13 @@ const ( const ( queryFmtInsertAuthenticationLogEntry = ` - INSERT INTO %s (time, successful, username) - VALUES (?, ?, ?);` + INSERT INTO %s (time, successful, banned, username, auth_type, remote_ip, request_uri, request_method) + VALUES (?, ?, ?, ?, ?, ?, ?, ?);` queryFmtSelect1FAAuthenticationLogEntryByUsername = ` SELECT time, successful, username FROM %s - WHERE time > ? AND username = ? + WHERE time > ? AND username = ? AND auth_type = '1FA' AND banned = 0 ORDER BY time DESC LIMIT ? OFFSET ?;` diff --git a/internal/storage/sql_provider_queries_special.go b/internal/storage/sql_provider_queries_special.go index 7e9ba24dd..370e44b79 100644 --- a/internal/storage/sql_provider_queries_special.go +++ b/internal/storage/sql_provider_queries_special.go @@ -21,8 +21,8 @@ const ( LIMIT 100 OFFSET ?;` queryFmtPre1To1InsertAuthenticationLogs = ` - INSERT INTO %s (username, successful, time) - VALUES (?, ?, ?);` + INSERT INTO %s (username, successful, time, request_uri) + VALUES (?, ?, ?, '');` queryFmtPre1InsertUserPreferencesFromSelect = ` INSERT INTO %s (username, second_factor_method)