[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

@@ -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
 }

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"`
+	Code          int    `json:"code"`
+	Message       string `json:"message"`
+	MessageDetail string `json:"message_detail"`
 	Stat          string `json:"stat"`
 }

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

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",

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)
 }

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")