authn: serialize ldap authn calls

Some LDAP servers are not MT-safe in that when searches happen with binds
in flight leads to errors such as:
"comment: No other operations may be performed on the connection while a
bind is outstanding"

Add goroutine-id in logs to help debug MT bugs.

Signed-off-by: Ramkumar Chinchani <rchincha@cisco.com>

pkg/api/authz.go

@@ -14,13 +14,13 @@ import (
 type contextKey int
 
 const (
-	// actions
+	// actions.
 	CREATE = "create"
 	READ   = "read"
 	UPDATE = "update"
 	DELETE = "delete"
 
-	// request-local context key
+	// request-local context key.
 	authzCtxKey contextKey = 0
 )
 

pkg/api/ldap.go

@@ -3,6 +3,7 @@
 package api
 
 import (
+	"sync"
 	"time"
 
 	"crypto/tls"
@@ -34,6 +35,7 @@ type LDAPClient struct {
 	ClientCertificates []tls.Certificate // Adding client certificates
 	ClientCAs          *x509.CertPool
 	Log                log.Logger
+	lock               sync.Mutex
 }
 
 // Connect connects to the ldap backend.
@@ -118,6 +120,10 @@ func sleepAndRetry(retries, maxRetries int) bool {
 
 // Authenticate authenticates the user against the ldap backend.
 func (lc *LDAPClient) Authenticate(username, password string) (bool, map[string]string, error) {
+	// serialize LDAP calls since some LDAP servers don't allow searches when binds are in flight
+	lc.lock.Lock()
+	defer lc.lock.Unlock()
+
 	if password == "" {
 		// RFC 4513 section 5.1.2
 		return false, nil, errors.ErrLDAPEmptyPassphrase
@@ -206,13 +212,5 @@ func (lc *LDAPClient) Authenticate(username, password string) (bool, map[string]
 		return false, user, err
 	}
 
-	// Rebind as the read only user for any further queries
-	if lc.BindDN != "" && lc.BindPassword != "" {
-		err = lc.Conn.Bind(lc.BindDN, lc.BindPassword)
-		if err != nil {
-			return true, user, err
-		}
-	}
-
 	return true, user, nil
 }

pkg/api/routes.go

@@ -943,7 +943,6 @@ func (rh *RouteHandler) PatchBlobUpload(w http.ResponseWriter, r *http.Request)
 // @Failure 500 {string} string "internal server error"
 // @Router /v2/{name}/blobs/uploads/{session_id} [put].
 func (rh *RouteHandler) UpdateBlobUpload(w http.ResponseWriter, r *http.Request) {
-	rh.c.Log.Info().Interface("headers", r.Header).Msg("HEADERS")
 	vars := mux.Vars(r)
 	name, ok := vars["name"]
 

pkg/log/log.go

@@ -4,6 +4,8 @@ import (
 	"encoding/base64"
 	"net/http"
 	"os"
+	"runtime"
+	"strconv"
 	"strings"
 	"time"
 
@@ -42,7 +44,7 @@ func NewLogger(level string, output string) Logger {
 		log = zerolog.New(file)
 	}
 
-	return Logger{Logger: log.With().Caller().Timestamp().Logger()}
+	return Logger{Logger: log.Hook(goroutineHook{}).With().Caller().Timestamp().Logger()}
 }
 
 func NewAuditLogger(level string, audit string) *Logger {
@@ -203,3 +205,25 @@ func SessionAuditLogger(audit *Logger) mux.MiddlewareFunc {
 		})
 	}
 }
+
+// goroutineID adds goroutine-id to logs to help debug concurrency issues.
+func goroutineID() int {
+	var buf [64]byte
+	n := runtime.Stack(buf[:], false)
+	idField := strings.Fields(strings.TrimPrefix(string(buf[:n]), "goroutine "))[0]
+
+	id, err := strconv.Atoi(idField)
+	if err != nil {
+		return -1
+	}
+
+	return id
+}
+
+type goroutineHook struct{}
+
+func (h goroutineHook) Run(e *zerolog.Event, level zerolog.Level, msg string) {
+	if level != zerolog.NoLevel {
+		e.Int("goroutine", goroutineID())
+	}
+}