outposts/ldap: improve logging, add request ID

Signed-off-by: Jens Langhammer <jens.langhammer@beryju.org>

internal/outpost/flow.go

@@ -41,8 +41,8 @@ type FlowExecutor struct {
 	token    string
 }
 
-func NewFlowExecutor(flowSlug string, refConfig *api.Configuration) *FlowExecutor {
+func NewFlowExecutor(flowSlug string, refConfig *api.Configuration, logFields log.Fields) *FlowExecutor {
-	l := log.WithField("flow", flowSlug)
+	l := log.WithField("flow", flowSlug).WithFields(logFields)
 	jar, err := cookiejar.New(nil)
 	if err != nil {
 		l.WithError(err).Warning("Failed to create cookiejar")
@@ -97,7 +97,7 @@ func (fe *FlowExecutor) CheckApplicationAccess(appSlug string) (bool, error) {
 	if err != nil {
 		return false, fmt.Errorf("failed to check access: %w", err)
 	}
-	fe.log.Info("User has access")
+	fe.log.Debug("User has access")
 	return true, nil
 }
 

internal/outpost/ldap/bind.go

@@ -4,20 +4,38 @@ import (
 	"net"
 	"strings"
 
+	"github.com/google/uuid"
 	"github.com/nmcclain/ldap"
+	log "github.com/sirupsen/logrus"
 )
 
+type BindRequest struct {
+	BindDN string
+	BindPW string
+	id     string
+	conn   net.Conn
+	log    *log.Entry
+}
+
 func (ls *LDAPServer) Bind(bindDN string, bindPW string, conn net.Conn) (ldap.LDAPResultCode, error) {
 	bindDN = strings.ToLower(bindDN)
-	ls.log.WithField("bindDN", bindDN).Info("bind")
+	rid := uuid.New().String()
+	req := BindRequest{
+		BindDN: bindDN,
+		BindPW: bindPW,
+		conn:   conn,
+		log:    ls.log.WithField("bindDN", bindDN).WithField("requestId", rid).WithField("client", conn.RemoteAddr().String()),
+		id:     rid,
+	}
+	req.log.Info("Bind request")
 	for _, instance := range ls.providers {
 		username, err := instance.getUsername(bindDN)
 		if err == nil {
-			return instance.Bind(username, bindDN, bindPW, conn)
+			return instance.Bind(username, req)
 		} else {
 			ls.log.WithError(err).Debug("Username not for instance")
 		}
 	}
-	ls.log.WithField("bindDN", bindDN).WithField("request", "bind").Warning("No provider found for request")
+	req.log.WithField("request", "bind").Warning("No provider found for request")
 	return ldap.LDAPResultOperationsError, nil
 }

internal/outpost/ldap/instance_bind.go

@@ -3,12 +3,12 @@ package ldap
 import (
 	"context"
 	"errors"
-	"net"
 	"strings"
 	"time"
 
 	goldap "github.com/go-ldap/ldap/v3"
 	"github.com/nmcclain/ldap"
+	log "github.com/sirupsen/logrus"
 	"goauthentik.io/api"
 	"goauthentik.io/internal/outpost"
 )
@@ -33,60 +33,68 @@ func (pi *ProviderInstance) getUsername(dn string) (string, error) {
 	return "", errors.New("failed to find cn")
 }
 
-func (pi *ProviderInstance) Bind(username string, bindDN, bindPW string, conn net.Conn) (ldap.LDAPResultCode, error) {
+func (pi *ProviderInstance) Bind(username string, req BindRequest) (ldap.LDAPResultCode, error) {
-	fe := outpost.NewFlowExecutor(pi.flowSlug, pi.s.ac.Client.GetConfig())
+	fe := outpost.NewFlowExecutor(pi.flowSlug, pi.s.ac.Client.GetConfig(), log.Fields{
-	fe.DelegateClientIP(conn.RemoteAddr())
+		"bindDN":    req.BindDN,
+		"client":    req.conn.RemoteAddr().String(),
+		"requestId": req.id,
+	})
+	fe.DelegateClientIP(req.conn.RemoteAddr())
 	fe.Params.Add("goauthentik.io/outpost/ldap", "true")
 
 	fe.Answers[outpost.StageIdentification] = username
-	fe.Answers[outpost.StagePassword] = bindPW
+	fe.Answers[outpost.StagePassword] = req.BindPW
 
 	passed, err := fe.Execute()
 	if !passed {
 		return ldap.LDAPResultInvalidCredentials, nil
 	}
 	if err != nil {
-		pi.log.WithField("bindDN", bindDN).WithError(err).Warning("failed to execute flow")
+		req.log.WithError(err).Warning("failed to execute flow")
 		return ldap.LDAPResultOperationsError, nil
 	}
 	access, err := fe.CheckApplicationAccess(pi.appSlug)
 	if !access {
-		pi.log.WithField("bindDN", bindDN).Info("Access denied for user")
+		req.log.Info("Access denied for user")
 		return ldap.LDAPResultInsufficientAccessRights, nil
 	}
 	if err != nil {
-		pi.log.WithField("bindDN", bindDN).WithError(err).Warning("failed to check access")
+		req.log.WithError(err).Warning("failed to check access")
 		return ldap.LDAPResultOperationsError, nil
 	}
-	pi.log.WithField("bindDN", bindDN).Info("User has access")
+	req.log.Info("User has access")
 	// Get user info to store in context
 	userInfo, _, err := fe.ApiClient().CoreApi.CoreUsersMeRetrieve(context.Background()).Execute()
 	if err != nil {
-		pi.log.WithField("bindDN", bindDN).WithError(err).Warning("failed to get user info")
+		req.log.WithError(err).Warning("failed to get user info")
 		return ldap.LDAPResultOperationsError, nil
 	}
 	pi.boundUsersMutex.Lock()
-	pi.boundUsers[bindDN] = UserFlags{
+	cs := pi.SearchAccessCheck(userInfo.User)
+	pi.boundUsers[req.BindDN] = UserFlags{
 		UserInfo:  userInfo.User,
-		CanSearch: pi.SearchAccessCheck(userInfo.User),
+		CanSearch: cs != nil,
 	}
+	if pi.boundUsers[req.BindDN].CanSearch {
+		req.log.WithField("group", cs).Info("Allowed access to search")
+	}
+
 	defer pi.boundUsersMutex.Unlock()
 	pi.delayDeleteUserInfo(username)
 	return ldap.LDAPResultSuccess, nil
 }
 
 // SearchAccessCheck Check if the current user is allowed to search
-func (pi *ProviderInstance) SearchAccessCheck(user api.User) bool {
+func (pi *ProviderInstance) SearchAccessCheck(user api.User) *string {
 	for _, group := range user.Groups {
 		for _, allowedGroup := range pi.searchAllowedGroups {
 			pi.log.WithField("userGroup", group.Pk).WithField("allowedGroup", allowedGroup).Trace("Checking search access")
 			if group.Pk == allowedGroup.String() {
-				pi.log.WithField("group", group.Name).Info("Allowed access to search")
+				return &group.Name
-				return true
 			}
 		}
 	}
-	return false
+	return nil
 }
 
 func (pi *ProviderInstance) delayDeleteUserInfo(dn string) {

internal/outpost/ldap/instance_search.go

@@ -4,50 +4,48 @@ import (
 	"context"
 	"errors"
 	"fmt"
-	"net"
 	"strings"
 
 	"github.com/nmcclain/ldap"
 	"goauthentik.io/api"
 )
 
-func (pi *ProviderInstance) SearchMe(user api.User, searchReq ldap.SearchRequest, conn net.Conn) (ldap.ServerSearchResult, error) {
+func (pi *ProviderInstance) SearchMe(user api.User) (ldap.ServerSearchResult, error) {
 	entries := make([]*ldap.Entry, 1)
 	entries[0] = pi.UserEntry(user)
 	return ldap.ServerSearchResult{Entries: entries, Referrals: []string{}, Controls: []ldap.Control{}, ResultCode: ldap.LDAPResultSuccess}, nil
 }
 
-func (pi *ProviderInstance) Search(bindDN string, searchReq ldap.SearchRequest, conn net.Conn) (ldap.ServerSearchResult, error) {
+func (pi *ProviderInstance) Search(req SearchRequest) (ldap.ServerSearchResult, error) {
-	bindDN = strings.ToLower(bindDN)
 	baseDN := strings.ToLower("," + pi.BaseDN)
 
 	entries := []*ldap.Entry{}
-	filterEntity, err := ldap.GetFilterObjectClass(searchReq.Filter)
+	filterEntity, err := ldap.GetFilterObjectClass(req.Filter)
 	if err != nil {
-		return ldap.ServerSearchResult{ResultCode: ldap.LDAPResultOperationsError}, fmt.Errorf("Search Error: error parsing filter: %s", searchReq.Filter)
+		return ldap.ServerSearchResult{ResultCode: ldap.LDAPResultOperationsError}, fmt.Errorf("Search Error: error parsing filter: %s", req.Filter)
 	}
-	if len(bindDN) < 1 {
+	if len(req.BindDN) < 1 {
-		return ldap.ServerSearchResult{ResultCode: ldap.LDAPResultInsufficientAccessRights}, fmt.Errorf("Search Error: Anonymous BindDN not allowed %s", bindDN)
+		return ldap.ServerSearchResult{ResultCode: ldap.LDAPResultInsufficientAccessRights}, fmt.Errorf("Search Error: Anonymous BindDN not allowed %s", req.BindDN)
 	}
-	if !strings.HasSuffix(bindDN, baseDN) {
+	if !strings.HasSuffix(req.BindDN, baseDN) {
-		return ldap.ServerSearchResult{ResultCode: ldap.LDAPResultInsufficientAccessRights}, fmt.Errorf("Search Error: BindDN %s not in our BaseDN %s", bindDN, pi.BaseDN)
+		return ldap.ServerSearchResult{ResultCode: ldap.LDAPResultInsufficientAccessRights}, fmt.Errorf("Search Error: BindDN %s not in our BaseDN %s", req.BindDN, pi.BaseDN)
 	}
 
 	pi.boundUsersMutex.RLock()
 	defer pi.boundUsersMutex.RUnlock()
-	flags, ok := pi.boundUsers[bindDN]
+	flags, ok := pi.boundUsers[req.BindDN]
 	if !ok {
 		pi.log.Debug("User info not cached")
 		return ldap.ServerSearchResult{ResultCode: ldap.LDAPResultInsufficientAccessRights}, errors.New("access denied")
 	}
 	if !flags.CanSearch {
 		pi.log.Debug("User can't search, showing info about user")
-		return pi.SearchMe(flags.UserInfo, searchReq, conn)
+		return pi.SearchMe(flags.UserInfo)
 	}
 
 	switch filterEntity {
 	default:
-		return ldap.ServerSearchResult{ResultCode: ldap.LDAPResultOperationsError}, fmt.Errorf("Search Error: unhandled filter type: %s [%s]", filterEntity, searchReq.Filter)
+		return ldap.ServerSearchResult{ResultCode: ldap.LDAPResultOperationsError}, fmt.Errorf("Search Error: unhandled filter type: %s [%s]", filterEntity, req.Filter)
 	case GroupObjectClass:
 		groups, _, err := pi.s.ac.Client.CoreApi.CoreGroupsList(context.Background()).Execute()
 		if err != nil {
@@ -76,7 +74,7 @@ func (pi *ProviderInstance) Search(bindDN string, searchReq ldap.SearchRequest,
 			entries = append(entries, pi.UserEntry(u))
 		}
 	}
-	pi.log.WithField("filter", searchReq.Filter).Debug("Search OK")
+	pi.log.WithField("filter", req.Filter).Debug("Search OK")
 	return ldap.ServerSearchResult{Entries: entries, Referrals: []string{}, Controls: []ldap.Control{}, ResultCode: ldap.LDAPResultSuccess}, nil
 }
 

internal/outpost/ldap/search.go

@@ -3,25 +3,46 @@ package ldap
 import (
 	"errors"
 	"net"
+	"strings"
 
 	goldap "github.com/go-ldap/ldap/v3"
+	"github.com/google/uuid"
 	"github.com/nmcclain/ldap"
+	log "github.com/sirupsen/logrus"
 )
 
+type SearchRequest struct {
+	ldap.SearchRequest
+	BindDN string
+	id     string
+	conn   net.Conn
+	log    *log.Entry
+}
+
 func (ls *LDAPServer) Search(bindDN string, searchReq ldap.SearchRequest, conn net.Conn) (ldap.ServerSearchResult, error) {
-	ls.log.WithField("bindDN", bindDN).WithField("baseDN", searchReq.BaseDN).Info("search")
+	bindDN = strings.ToLower(bindDN)
+	rid := uuid.New().String()
+	req := SearchRequest{
+		SearchRequest: searchReq,
+		BindDN:        bindDN,
+		conn:          conn,
+		log:           ls.log.WithField("bindDN", bindDN).WithField("requestId", rid).WithField("client", conn.RemoteAddr().String()).WithField("filter", searchReq.Filter).WithField("baseDN", searchReq.BaseDN),
+		id:            rid,
+	}
+	req.log.Info("Search request")
+
 	if searchReq.BaseDN == "" {
 		return ldap.ServerSearchResult{ResultCode: ldap.LDAPResultSuccess}, nil
 	}
 	bd, err := goldap.ParseDN(searchReq.BaseDN)
 	if err != nil {
-		ls.log.WithField("baseDN", searchReq.BaseDN).WithError(err).Info("failed to parse basedn")
+		req.log.WithError(err).Info("failed to parse basedn")
 		return ldap.ServerSearchResult{ResultCode: ldap.LDAPResultOperationsError}, errors.New("invalid DN")
 	}
 	for _, provider := range ls.providers {
 		providerBase, _ := goldap.ParseDN(provider.BaseDN)
 		if providerBase.AncestorOf(bd) {
-			return provider.Search(bindDN, searchReq, conn)
+			return provider.Search(req)
 		}
 	}
 	return ldap.ServerSearchResult{ResultCode: ldap.LDAPResultOperationsError}, errors.New("no provider could handle request")