From 898f2a807e9a0ef33179d4e3f43c4560b5ec21a9 Mon Sep 17 00:00:00 2001 From: James Elliott Date: Sun, 1 Mar 2020 11:51:11 +1100 Subject: [PATCH] [MISC] Add Detailed DUO Push Logging (#664) * [MISC] Add Detailed DUO Push Logging - Added trace logging for all response data from the DUO API - Added warning messages on auth failures - Added debug logging when DUO auth begins - Updated mocks/unit tests to use the AutheliaCtx as required --- internal/duo/duo.go | 7 +++++-- internal/duo/types.go | 13 ++++++++++--- internal/handlers/handler_sign_duo.go | 18 ++++++++++++++++-- internal/handlers/handler_sign_duo_test.go | 16 ++++++++-------- internal/mocks/mock_duo_api.go | 9 +++++---- internal/server/server.go | 2 +- 6 files changed, 45 insertions(+), 20 deletions(-) diff --git a/internal/duo/duo.go b/internal/duo/duo.go index 13f924b54..84a6f2595 100644 --- a/internal/duo/duo.go +++ b/internal/duo/duo.go @@ -5,6 +5,8 @@ import ( "net/url" "github.com/duosecurity/duo_api_golang" + + "github.com/authelia/authelia/internal/middlewares" ) // NewDuoAPI create duo API instance @@ -15,18 +17,19 @@ func NewDuoAPI(duoAPI *duoapi.DuoApi) *APIImpl { } // Call call to the DuoAPI -func (d *APIImpl) Call(values url.Values) (*Response, error) { +func (d *APIImpl) Call(values url.Values, ctx *middlewares.AutheliaCtx) (*Response, error) { _, responseBytes, err := d.DuoApi.SignedCall("POST", "/auth/v2/auth", values) if err != nil { return nil, err } + ctx.Logger.Tracef("Duo Push Auth Response Raw Data for %s from IP %s: %s", ctx.GetSession().Username, ctx.RemoteIP().String(), string(responseBytes)) + var response Response err = json.Unmarshal(responseBytes, &response) if err != nil { return nil, err } - return &response, nil } diff --git a/internal/duo/types.go b/internal/duo/types.go index 8f529c986..0ba4bad62 100644 --- a/internal/duo/types.go +++ b/internal/duo/types.go @@ -1,11 +1,15 @@ package duo -import "net/url" +import ( + "net/url" + + "github.com/authelia/authelia/internal/middlewares" +) import "github.com/duosecurity/duo_api_golang" // API interface wrapping duo api library for testing purpose type API interface { - Call(values url.Values) (*Response, error) + Call(values url.Values, ctx *middlewares.AutheliaCtx) (*Response, error) } // APIImpl implementation of DuoAPI interface @@ -20,5 +24,8 @@ type Response struct { Status string `json:"status"` StatusMessage string `json:"status_msg"` } `json:"response"` - Stat string `json:"stat"` + Code int `json:"code"` + Message string `json:"message"` + MessageDetail string `json:"message_detail"` + Stat string `json:"stat"` } diff --git a/internal/handlers/handler_sign_duo.go b/internal/handlers/handler_sign_duo.go index 85b6d8b1c..cab4ba161 100644 --- a/internal/handlers/handler_sign_duo.go +++ b/internal/handlers/handler_sign_duo.go @@ -21,23 +21,37 @@ func SecondFactorDuoPost(duoAPI duo.API) middlewares.RequestHandler { } userSession := ctx.GetSession() + remoteIP := ctx.RemoteIP().String() + + ctx.Logger.Debugf("Starting Duo Push Auth Attempt for %s from 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", ctx.RemoteIP().String()) + values.Set("ipaddr", remoteIP) values.Set("factor", "push") values.Set("device", "auto") if requestBody.TargetURL != "" { values.Set("pushinfo", fmt.Sprintf("target%%20url=%s", requestBody.TargetURL)) } - duoResponse, err := duoAPI.Call(values) + duoResponse, err := duoAPI.Call(values, ctx) if err != nil { ctx.Error(fmt.Errorf("Duo API errored: %s", err), mfaValidationFailedMessage) return } + if duoResponse.Stat == "FAIL" { + if duoResponse.Code == 40002 { + ctx.Logger.Warnf("Duo Push Auth failed to process the auth request for %s from %s: %s (%s), error code %d. "+ + "This error often occurs if you've not setup the username in the Admin Dashboard.", + userSession.Username, remoteIP, duoResponse.Message, duoResponse.MessageDetail, duoResponse.Code) + } else { + ctx.Logger.Warnf("Duo Push Auth failed to process the auth request for %s from %s: %s (%s), error code %d.", + userSession.Username, remoteIP, duoResponse.Message, duoResponse.MessageDetail, duoResponse.Code) + } + } + if duoResponse.Response.Result != "allow" { ctx.ReplyUnauthorized() return diff --git a/internal/handlers/handler_sign_duo_test.go b/internal/handlers/handler_sign_duo_test.go index e0d8202cd..2d0629333 100644 --- a/internal/handlers/handler_sign_duo_test.go +++ b/internal/handlers/handler_sign_duo_test.go @@ -44,7 +44,7 @@ func (s *SecondFactorDuoPostSuite) TestShouldCallDuoAPIAndAllowAccess() { response := duo.Response{} response.Response.Result = "allow" - duoMock.EXPECT().Call(gomock.Eq(values)).Return(&response, nil) + duoMock.EXPECT().Call(gomock.Eq(values), s.mock.Ctx).Return(&response, nil) s.mock.Ctx.Request.SetBodyString("{\"targetURL\": \"https://target.example.com\"}") @@ -66,7 +66,7 @@ func (s *SecondFactorDuoPostSuite) TestShouldCallDuoAPIAndDenyAccess() { response := duo.Response{} response.Response.Result = "deny" - duoMock.EXPECT().Call(gomock.Eq(values)).Return(&response, nil) + duoMock.EXPECT().Call(gomock.Eq(values), s.mock.Ctx).Return(&response, nil) s.mock.Ctx.Request.SetBodyString("{\"targetURL\": \"https://target.example.com\"}") @@ -85,7 +85,7 @@ func (s *SecondFactorDuoPostSuite) TestShouldCallDuoAPIAndFail() { values.Set("device", "auto") values.Set("pushinfo", "target%20url=https://target.example.com") - duoMock.EXPECT().Call(gomock.Eq(values)).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\"}") @@ -100,7 +100,7 @@ func (s *SecondFactorDuoPostSuite) TestShouldRedirectUserToDefaultURL() { response := duo.Response{} response.Response.Result = "allow" - duoMock.EXPECT().Call(gomock.Any()).Return(&response, nil) + duoMock.EXPECT().Call(gomock.Any(), s.mock.Ctx).Return(&response, nil) s.mock.Ctx.Configuration.DefaultRedirectionURL = "http://redirection.local" @@ -120,7 +120,7 @@ func (s *SecondFactorDuoPostSuite) TestShouldNotReturnRedirectURL() { response := duo.Response{} response.Response.Result = "allow" - duoMock.EXPECT().Call(gomock.Any()).Return(&response, nil) + duoMock.EXPECT().Call(gomock.Any(), s.mock.Ctx).Return(&response, nil) bodyBytes, err := json.Marshal(signDuoRequestBody{}) s.Require().NoError(err) @@ -136,7 +136,7 @@ func (s *SecondFactorDuoPostSuite) TestShouldRedirectUserToSafeTargetURL() { response := duo.Response{} response.Response.Result = "allow" - duoMock.EXPECT().Call(gomock.Any()).Return(&response, nil) + duoMock.EXPECT().Call(gomock.Any(), s.mock.Ctx).Return(&response, nil) bodyBytes, err := json.Marshal(signDuoRequestBody{ TargetURL: "https://mydomain.local", @@ -156,7 +156,7 @@ func (s *SecondFactorDuoPostSuite) TestShouldNotRedirectToUnsafeURL() { response := duo.Response{} response.Response.Result = "allow" - duoMock.EXPECT().Call(gomock.Any()).Return(&response, nil) + duoMock.EXPECT().Call(gomock.Any(), s.mock.Ctx).Return(&response, nil) bodyBytes, err := json.Marshal(signDuoRequestBody{ TargetURL: "http://mydomain.local", @@ -174,7 +174,7 @@ func (s *SecondFactorDuoPostSuite) TestShouldRegenerateSessionForPreventingSessi response := duo.Response{} response.Response.Result = "allow" - duoMock.EXPECT().Call(gomock.Any()).Return(&response, nil) + duoMock.EXPECT().Call(gomock.Any(), s.mock.Ctx).Return(&response, nil) bodyBytes, err := json.Marshal(signDuoRequestBody{ TargetURL: "http://mydomain.local", diff --git a/internal/mocks/mock_duo_api.go b/internal/mocks/mock_duo_api.go index 3bc692bd2..e4dff156d 100644 --- a/internal/mocks/mock_duo_api.go +++ b/internal/mocks/mock_duo_api.go @@ -9,6 +9,7 @@ import ( reflect "reflect" duo "github.com/authelia/authelia/internal/duo" + "github.com/authelia/authelia/internal/middlewares" gomock "github.com/golang/mock/gomock" ) @@ -36,16 +37,16 @@ func (m *MockAPI) EXPECT() *MockAPIMockRecorder { } // Call mocks base method -func (m *MockAPI) Call(arg0 url.Values) (*duo.Response, error) { +func (m *MockAPI) Call(arg0 url.Values, arg1 *middlewares.AutheliaCtx) (*duo.Response, error) { m.ctrl.T.Helper() - ret := m.ctrl.Call(m, "Call", arg0) + ret := m.ctrl.Call(m, "Call", arg0, arg1) ret0, _ := ret[0].(*duo.Response) ret1, _ := ret[1].(error) return ret0, ret1 } // Call indicates an expected call of Call -func (mr *MockAPIMockRecorder) Call(arg0 interface{}) *gomock.Call { +func (mr *MockAPIMockRecorder) Call(arg0, arg1 interface{}) *gomock.Call { mr.mock.ctrl.T.Helper() - return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "Call", reflect.TypeOf((*MockAPI)(nil).Call), arg0) + return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "Call", reflect.TypeOf((*MockAPI)(nil).Call), arg0, arg1) } diff --git a/internal/server/server.go b/internal/server/server.go index 4cf62bcdd..057c02e16 100644 --- a/internal/server/server.go +++ b/internal/server/server.go @@ -25,7 +25,7 @@ func StartServer(configuration schema.Configuration, providers middlewares.Provi if publicDir == "" { publicDir = "./public_html" } - fmt.Println("Selected public_html directory is ", publicDir) + logging.Logger().Infof("Selected public_html directory is %s", publicDir) router.GET("/", fasthttp.FSHandler(publicDir, 0)) router.ServeFiles("/static/*filepath", publicDir+"/static")