Merge pull request #1021 from ericchiang/debug-logs

*: add log events for login, LDAP queries, and SAML responses

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)

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

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

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
 }