From aad328bb35e05ab440a11054b23cc56b09ed1883 Mon Sep 17 00:00:00 2001 From: Eric Chiang Date: Fri, 11 Aug 2017 10:17:30 -0700 Subject: [PATCH] *: add log events for login, LDAP queries, and SAML responses --- connector/ldap/ldap.go | 22 +++++++++++++++++++++- connector/saml/saml.go | 5 +++++ connector/saml/types.go | 27 +++++++++++++++++++++++++++ server/handlers.go | 11 +++++++++++ 4 files changed, 64 insertions(+), 1 deletion(-) diff --git a/connector/ldap/ldap.go b/connector/ldap/ldap.go index 9107031a..01125ae7 100644 --- a/connector/ldap/ldap.go +++ b/connector/ldap/ldap.go @@ -127,6 +127,19 @@ type Config struct { } `json:"groupSearch"` } +func scopeString(i int) string { + switch i { + case ldap.ScopeBaseObject: + return "base" + case ldap.ScopeSingleLevel: + return "one" + case ldap.ScopeWholeSubtree: + return "sub" + default: + return "" + } +} + func parseScope(s string) (int, bool) { // NOTE(ericchiang): ScopeBaseObject doesn't really make sense for us because we // never know the user's or group's DN. @@ -342,6 +355,9 @@ func (c *ldapConnector) userEntry(conn *ldap.Conn, username string) (user ldap.E if c.UserSearch.NameAttr != "" { req.Attributes = append(req.Attributes, c.UserSearch.NameAttr) } + + c.logger.Infof("performing ldap search %s %s %s", + req.BaseDN, scopeString(req.Scope), req.Filter) resp, err := conn.Search(req) if err != nil { return ldap.Entry{}, false, fmt.Errorf("ldap: search with filter %q failed: %v", req.Filter, err) @@ -352,7 +368,9 @@ func (c *ldapConnector) userEntry(conn *ldap.Conn, username string) (user ldap.E c.logger.Errorf("ldap: no results returned for filter: %q", filter) return ldap.Entry{}, false, nil case 1: - return *resp.Entries[0], true, nil + user = *resp.Entries[0] + c.logger.Infof("username %q mapped to entry %s", username, user.DN) + return user, true, nil default: return ldap.Entry{}, false, fmt.Errorf("ldap: filter returned multiple (%d) results: %q", n, filter) } @@ -493,6 +511,8 @@ func (c *ldapConnector) groups(ctx context.Context, user ldap.Entry) ([]string, gotGroups := false if err := c.do(ctx, func(conn *ldap.Conn) error { + c.logger.Infof("performing ldap search %s %s %s", + req.BaseDN, scopeString(req.Scope), req.Filter) resp, err := conn.Search(req) if err != nil { return fmt.Errorf("ldap: search failed: %v", err) diff --git a/connector/saml/saml.go b/connector/saml/saml.go index 706ba95b..f35f0a81 100644 --- a/connector/saml/saml.go +++ b/connector/saml/saml.go @@ -366,6 +366,11 @@ func (p *provider) HandlePOST(s connector.Scopes, samlResponse, inResponseTo str return ident, fmt.Errorf("response did not contain a AttributeStatement") } + // Log the actual attributes we got back from the server. This helps debug + // configuration errors on the server side, where the SAML server doesn't + // send us the correct attributes. + p.logger.Infof("parsed and verified saml response attributes %s", attributes) + // Grab the email. if ident.Email, _ = attributes.get(p.emailAttr); ident.Email == "" { return ident, fmt.Errorf("no attribute with name %q: %s", p.emailAttr, attributes.names()) diff --git a/connector/saml/types.go b/connector/saml/types.go index 1f7d919e..c8d7e7f3 100644 --- a/connector/saml/types.go +++ b/connector/saml/types.go @@ -1,6 +1,7 @@ package saml import ( + "bytes" "encoding/xml" "fmt" "time" @@ -233,6 +234,18 @@ func (a *attributeStatement) names() []string { return s } +// String is a formatter for logging an attribute statement's sub statements. +func (a *attributeStatement) String() string { + buff := new(bytes.Buffer) + for i, attr := range a.Attributes { + if i != 0 { + buff.WriteString(", ") + } + buff.WriteString(attr.String()) + } + return buff.String() +} + type attribute struct { XMLName xml.Name `xml:"urn:oasis:names:tc:SAML:2.0:assertion Attribute"` @@ -248,3 +261,17 @@ type attributeValue struct { XMLName xml.Name `xml:"AttributeValue"` Value string `xml:",chardata"` } + +func (a attribute) String() string { + if len(a.AttributeValues) == 1 { + // "email" = "jane.doe@coreos.com" + return fmt.Sprintf("%q = %q", a.Name, a.AttributeValues[0].Value) + } + values := make([]string, len(a.AttributeValues)) + for i, av := range a.AttributeValues { + values[i] = av.Value + } + + // "groups" = ["engineering", "docs"] + return fmt.Sprintf("%q = %q", a.Name, values) +} diff --git a/server/handlers.go b/server/handlers.go index 683c6c20..a70858a9 100644 --- a/server/handlers.go +++ b/server/handlers.go @@ -390,6 +390,8 @@ func (s *Server) handleConnectorCallback(w http.ResponseWriter, r *http.Request) http.Redirect(w, r, redirectURL, http.StatusSeeOther) } +// finalizeLogin associates the user's identity with the current AuthRequest, then returns +// the approval page's path. func (s *Server) finalizeLogin(identity connector.Identity, authReq storage.AuthRequest, conn connector.Connector) (string, error) { claims := storage.Claims{ UserID: identity.UserID, @@ -408,6 +410,15 @@ func (s *Server) finalizeLogin(identity connector.Identity, authReq storage.Auth if err := s.storage.UpdateAuthRequest(authReq.ID, updater); err != nil { return "", fmt.Errorf("failed to update auth request: %v", err) } + + email := claims.Email + if !claims.EmailVerified { + email = email + " (unverified)" + } + + s.logger.Infof("login successful: connector %q, username=%q, email=%q, groups=%q", + authReq.ConnectorID, claims.Username, email, claims.Groups) + return path.Join(s.issuerURL.Path, "/approval") + "?req=" + authReq.ID, nil }