From d87871f806947a41007d38403f7377c599449d68 Mon Sep 17 00:00:00 2001 From: Jens Langhammer Date: Mon, 19 Jul 2021 13:41:29 +0200 Subject: [PATCH] outposts/ldap: improve logging, add request ID Signed-off-by: Jens Langhammer --- internal/outpost/flow.go | 6 ++-- internal/outpost/ldap/bind.go | 24 ++++++++++++-- internal/outpost/ldap/instance_bind.go | 40 ++++++++++++++---------- internal/outpost/ldap/instance_search.go | 26 +++++++-------- internal/outpost/ldap/search.go | 27 ++++++++++++++-- 5 files changed, 84 insertions(+), 39 deletions(-) diff --git a/internal/outpost/flow.go b/internal/outpost/flow.go index c98b86245..3141692ed 100644 --- a/internal/outpost/flow.go +++ b/internal/outpost/flow.go @@ -41,8 +41,8 @@ type FlowExecutor struct { token string } -func NewFlowExecutor(flowSlug string, refConfig *api.Configuration) *FlowExecutor { - l := log.WithField("flow", flowSlug) +func NewFlowExecutor(flowSlug string, refConfig *api.Configuration, logFields log.Fields) *FlowExecutor { + 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 } diff --git a/internal/outpost/ldap/bind.go b/internal/outpost/ldap/bind.go index 0988850f4..6dcae5102 100644 --- a/internal/outpost/ldap/bind.go +++ b/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 } diff --git a/internal/outpost/ldap/instance_bind.go b/internal/outpost/ldap/instance_bind.go index b9c7860fd..b3432e570 100644 --- a/internal/outpost/ldap/instance_bind.go +++ b/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) { - fe := outpost.NewFlowExecutor(pi.flowSlug, pi.s.ac.Client.GetConfig()) - fe.DelegateClientIP(conn.RemoteAddr()) +func (pi *ProviderInstance) Bind(username string, req BindRequest) (ldap.LDAPResultCode, error) { + fe := outpost.NewFlowExecutor(pi.flowSlug, pi.s.ac.Client.GetConfig(), log.Fields{ + "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 true + return &group.Name } } } - return false + return nil } func (pi *ProviderInstance) delayDeleteUserInfo(dn string) { diff --git a/internal/outpost/ldap/instance_search.go b/internal/outpost/ldap/instance_search.go index 52a4defca..31e6f89fa 100644 --- a/internal/outpost/ldap/instance_search.go +++ b/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) { - bindDN = strings.ToLower(bindDN) +func (pi *ProviderInstance) Search(req SearchRequest) (ldap.ServerSearchResult, error) { 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 { - return ldap.ServerSearchResult{ResultCode: ldap.LDAPResultInsufficientAccessRights}, fmt.Errorf("Search Error: Anonymous BindDN not allowed %s", bindDN) + if len(req.BindDN) < 1 { + return ldap.ServerSearchResult{ResultCode: ldap.LDAPResultInsufficientAccessRights}, fmt.Errorf("Search Error: Anonymous BindDN not allowed %s", req.BindDN) } - if !strings.HasSuffix(bindDN, baseDN) { - return ldap.ServerSearchResult{ResultCode: ldap.LDAPResultInsufficientAccessRights}, fmt.Errorf("Search Error: BindDN %s not in our BaseDN %s", bindDN, pi.BaseDN) + if !strings.HasSuffix(req.BindDN, 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 } diff --git a/internal/outpost/ldap/search.go b/internal/outpost/ldap/search.go index ab00a71bc..f2214c55b 100644 --- a/internal/outpost/ldap/search.go +++ b/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")