debug: Add X-Amz-Request-ID to lock/unlock calls (#16309)

internal/dsync/drwmutex.go

@@ -27,6 +27,7 @@ import (
 	"sync"
 	"time"
 
+	"github.com/minio/minio/internal/mcontext"
 	"github.com/minio/pkg/console"
 )
 
@@ -429,6 +430,15 @@ func lock(ctx context.Context, ds *Dsync, locks *[]string, id, source string, is
 	// Combined timeout for the lock attempt.
 	ctx, cancel := context.WithTimeout(ctx, ds.Timeouts.Acquire)
 	defer cancel()
+
+	// Special context for NetLockers - do not use timeouts.
+	// Also, pass the trace context info if found for debugging
+	netLockCtx := context.Background()
+	tc, ok := ctx.Value(mcontext.ContextTraceKey).(*mcontext.TraceCtxt)
+	if ok {
+		netLockCtx = context.WithValue(netLockCtx, mcontext.ContextTraceKey, tc)
+	}
+
 	for index, c := range restClnts {
 		wg.Add(1)
 		// broadcast lock request to all nodes
@@ -445,11 +455,11 @@ func lock(ctx context.Context, ds *Dsync, locks *[]string, id, source string, is
 			var locked bool
 			var err error
 			if isReadLock {
-				if locked, err = c.RLock(context.Background(), args); err != nil {
+				if locked, err = c.RLock(netLockCtx, args); err != nil {
 					log("dsync: Unable to call RLock failed with %s for %#v at %s\n", err, args, c)
 				}
 			} else {
-				if locked, err = c.Lock(context.Background(), args); err != nil {
+				if locked, err = c.Lock(netLockCtx, args); err != nil {
 					log("dsync: Unable to call Lock failed with %s for %#v at %s\n", err, args, c)
 				}
 			}
@@ -502,7 +512,7 @@ func lock(ctx context.Context, ds *Dsync, locks *[]string, id, source string, is
 	if !quorumLocked {
 		log("dsync: Unable to acquire lock in quorum %#v\n", args)
 		// Release all acquired locks without quorum.
-		if !releaseAll(ds, tolerance, owner, locks, isReadLock, restClnts, names...) {
+		if !releaseAll(ctx, ds, tolerance, owner, locks, isReadLock, restClnts, names...) {
 			log("Unable to release acquired locks, these locks will expire automatically %#v\n", args)
 		}
 	}
@@ -515,7 +525,7 @@ func lock(ctx context.Context, ds *Dsync, locks *[]string, id, source string, is
 			if grantToBeReleased.isLocked() {
 				// release abandoned lock
 				log("Releasing abandoned lock\n")
-				sendRelease(ds, restClnts[grantToBeReleased.index],
+				sendRelease(ctx, ds, restClnts[grantToBeReleased.index],
 					owner, grantToBeReleased.lockUID, isReadLock, names...)
 			}
 		}
@@ -564,13 +574,13 @@ func checkQuorumLocked(locks *[]string, quorum int) bool {
 }
 
 // releaseAll releases all locks that are marked as locked
-func releaseAll(ds *Dsync, tolerance int, owner string, locks *[]string, isReadLock bool, restClnts []NetLocker, names ...string) bool {
+func releaseAll(ctx context.Context, ds *Dsync, tolerance int, owner string, locks *[]string, isReadLock bool, restClnts []NetLocker, names ...string) bool {
 	var wg sync.WaitGroup
 	for lockID := range restClnts {
 		wg.Add(1)
 		go func(lockID int) {
 			defer wg.Done()
-			if sendRelease(ds, restClnts[lockID], owner, (*locks)[lockID], isReadLock, names...) {
+			if sendRelease(ctx, ds, restClnts[lockID], owner, (*locks)[lockID], isReadLock, names...) {
 				(*locks)[lockID] = ""
 			}
 		}(lockID)
@@ -587,7 +597,7 @@ func releaseAll(ds *Dsync, tolerance int, owner string, locks *[]string, isReadL
 // Unlock unlocks the write lock.
 //
 // It is a run-time error if dm is not locked on entry to Unlock.
-func (dm *DRWMutex) Unlock() {
+func (dm *DRWMutex) Unlock(ctx context.Context) {
 	dm.m.Lock()
 	dm.cancelRefresh()
 	dm.m.Unlock()
@@ -620,7 +630,7 @@ func (dm *DRWMutex) Unlock() {
 	tolerance := len(restClnts) / 2
 
 	isReadLock := false
-	for !releaseAll(dm.clnt, tolerance, owner, &locks, isReadLock, restClnts, dm.Names...) {
+	for !releaseAll(ctx, dm.clnt, tolerance, owner, &locks, isReadLock, restClnts, dm.Names...) {
 		time.Sleep(time.Duration(dm.rng.Float64() * float64(dm.lockRetryInterval)))
 	}
 }
@@ -628,7 +638,7 @@ func (dm *DRWMutex) Unlock() {
 // RUnlock releases a read lock held on dm.
 //
 // It is a run-time error if dm is not locked on entry to RUnlock.
-func (dm *DRWMutex) RUnlock() {
+func (dm *DRWMutex) RUnlock(ctx context.Context) {
 	dm.m.Lock()
 	dm.cancelRefresh()
 	dm.m.Unlock()
@@ -661,13 +671,13 @@ func (dm *DRWMutex) RUnlock() {
 	tolerance := len(restClnts) / 2
 
 	isReadLock := true
-	for !releaseAll(dm.clnt, tolerance, owner, &locks, isReadLock, restClnts, dm.Names...) {
+	for !releaseAll(ctx, dm.clnt, tolerance, owner, &locks, isReadLock, restClnts, dm.Names...) {
 		time.Sleep(time.Duration(dm.rng.Float64() * float64(dm.lockRetryInterval)))
 	}
 }
 
 // sendRelease sends a release message to a node that previously granted a lock
-func sendRelease(ds *Dsync, c NetLocker, owner string, uid string, isReadLock bool, names ...string) bool {
+func sendRelease(ctx context.Context, ds *Dsync, c NetLocker, owner string, uid string, isReadLock bool, names ...string) bool {
 	if c == nil {
 		log("Unable to call RUnlock failed with %s\n", errors.New("netLocker is offline"))
 		return false
@@ -683,16 +693,21 @@ func sendRelease(ds *Dsync, c NetLocker, owner string, uid string, isReadLock bo
 		Resources: names,
 	}
 
-	ctx, cancel := context.WithTimeout(context.Background(), ds.Timeouts.UnlockCall)
+	netLockCtx, cancel := context.WithTimeout(context.Background(), ds.Timeouts.UnlockCall)
 	defer cancel()
 
+	tc, ok := ctx.Value(mcontext.ContextTraceKey).(*mcontext.TraceCtxt)
+	if ok {
+		netLockCtx = context.WithValue(netLockCtx, mcontext.ContextTraceKey, tc)
+	}
+
 	if isReadLock {
-		if _, err := c.RUnlock(ctx, args); err != nil {
+		if _, err := c.RUnlock(netLockCtx, args); err != nil {
 			log("dsync: Unable to call RUnlock failed with %s for %#v at %s\n", err, args, c)
 			return false
 		}
 	} else {
-		if _, err := c.Unlock(ctx, args); err != nil {
+		if _, err := c.Unlock(netLockCtx, args); err != nil {
 			log("dsync: Unable to call Unlock failed with %s for %#v at %s\n", err, args, c)
 			return false
 		}

internal/dsync/drwmutex_test.go

@@ -48,13 +48,13 @@ func testSimpleWriteLock(t *testing.T, duration time.Duration) (locked bool) {
 
 	go func() {
 		time.Sleep(2 * testDrwMutexAcquireTimeout)
-		drwm1.RUnlock()
+		drwm1.RUnlock(context.Background())
 		// fmt.Println("1st read lock released, waiting...")
 	}()
 
 	go func() {
 		time.Sleep(3 * testDrwMutexAcquireTimeout)
-		drwm2.RUnlock()
+		drwm2.RUnlock(context.Background())
 		// fmt.Println("2nd read lock released, waiting...")
 	}()
 
@@ -66,7 +66,7 @@ func testSimpleWriteLock(t *testing.T, duration time.Duration) (locked bool) {
 		// fmt.Println("Write lock acquired, waiting...")
 		time.Sleep(testDrwMutexAcquireTimeout)
 
-		drwm3.Unlock()
+		drwm3.Unlock(context.Background())
 	}
 	// fmt.Println("Write lock failed due to timeout")
 	return
@@ -101,7 +101,7 @@ func testDualWriteLock(t *testing.T, duration time.Duration) (locked bool) {
 
 	go func() {
 		time.Sleep(3 * testDrwMutexAcquireTimeout)
-		drwm1.Unlock()
+		drwm1.Unlock(context.Background())
 		// fmt.Println("Initial write lock released, waiting...")
 	}()
 
@@ -113,7 +113,7 @@ func testDualWriteLock(t *testing.T, duration time.Duration) (locked bool) {
 		// fmt.Println("2nd write lock acquired, waiting...")
 		time.Sleep(testDrwMutexAcquireTimeout)
 
-		drwm2.Unlock()
+		drwm2.Unlock(context.Background())
 	}
 	// fmt.Println("2nd write lock failed due to timeout")
 	return
@@ -144,7 +144,7 @@ func parallelReader(ctx context.Context, m *DRWMutex, clocked, cunlock, cdone ch
 	if m.GetRLock(ctx, nil, id, source, Options{Timeout: time.Second}) {
 		clocked <- true
 		<-cunlock
-		m.RUnlock()
+		m.RUnlock(context.Background())
 		cdone <- true
 	}
 }
@@ -193,7 +193,7 @@ func reader(resource string, numIterations int, activity *int32, cdone chan bool
 			for i := 0; i < 100; i++ {
 			}
 			atomic.AddInt32(activity, -1)
-			rwm.RUnlock()
+			rwm.RUnlock(context.Background())
 		}
 	}
 	cdone <- true
@@ -211,7 +211,7 @@ func writer(resource string, numIterations int, activity *int32, cdone chan bool
 			for i := 0; i < 100; i++ {
 			}
 			atomic.AddInt32(activity, -10000)
-			rwm.Unlock()
+			rwm.Unlock(context.Background())
 		}
 	}
 	cdone <- true
@@ -268,7 +268,7 @@ func TestUnlockPanic(t *testing.T) {
 		}
 	}()
 	mu := NewDRWMutex(ds, "test")
-	mu.Unlock()
+	mu.Unlock(context.Background())
 }
 
 // Borrowed from rwmutex_test.go
@@ -278,10 +278,10 @@ func TestUnlockPanic2(t *testing.T) {
 		if recover() == nil {
 			t.Fatalf("unlock of unlocked RWMutex did not panic")
 		}
-		mu.RUnlock() // Unlock, so -test.count > 1 works
+		mu.RUnlock(context.Background()) // Unlock, so -test.count > 1 works
 	}()
 	mu.RLock(id, source)
-	mu.Unlock()
+	mu.Unlock(context.Background())
 }
 
 // Borrowed from rwmutex_test.go
@@ -292,7 +292,7 @@ func TestRUnlockPanic(t *testing.T) {
 		}
 	}()
 	mu := NewDRWMutex(ds, "test")
-	mu.RUnlock()
+	mu.RUnlock(context.Background())
 }
 
 // Borrowed from rwmutex_test.go
@@ -302,10 +302,10 @@ func TestRUnlockPanic2(t *testing.T) {
 		if recover() == nil {
 			t.Fatalf("read unlock of unlocked RWMutex did not panic")
 		}
-		mu.Unlock() // Unlock, so -test.count > 1 works
+		mu.Unlock(context.Background()) // Unlock, so -test.count > 1 works
 	}()
 	mu.Lock(id, source)
-	mu.RUnlock()
+	mu.RUnlock(context.Background())
 }
 
 // Borrowed from rwmutex_test.go
@@ -320,14 +320,14 @@ func benchmarkRWMutex(b *testing.B, localWork, writeRatio int) {
 			foo++
 			if foo%writeRatio == 0 {
 				rwm.Lock(id, source)
-				rwm.Unlock()
+				rwm.Unlock(context.Background())
 			} else {
 				rwm.RLock(id, source)
 				for i := 0; i != localWork; i++ {
 					foo *= 2
 					foo /= 2
 				}
-				rwm.RUnlock()
+				rwm.RUnlock(context.Background())
 			}
 		}
 		_ = foo

internal/dsync/dsync_test.go

@@ -69,7 +69,7 @@ func TestSimpleLock(t *testing.T) {
 	// fmt.Println("Lock acquired, waiting...")
 	time.Sleep(testDrwMutexRefreshCallTimeout)
 
-	dm.Unlock()
+	dm.Unlock(context.Background())
 }
 
 func TestSimpleLockUnlockMultipleTimes(t *testing.T) {
@@ -77,23 +77,23 @@ func TestSimpleLockUnlockMultipleTimes(t *testing.T) {
 
 	dm.Lock(id, source)
 	time.Sleep(time.Duration(10+(rand.Float32()*50)) * time.Millisecond)
-	dm.Unlock()
+	dm.Unlock(context.Background())
 
 	dm.Lock(id, source)
 	time.Sleep(time.Duration(10+(rand.Float32()*50)) * time.Millisecond)
-	dm.Unlock()
+	dm.Unlock(context.Background())
 
 	dm.Lock(id, source)
 	time.Sleep(time.Duration(10+(rand.Float32()*50)) * time.Millisecond)
-	dm.Unlock()
+	dm.Unlock(context.Background())
 
 	dm.Lock(id, source)
 	time.Sleep(time.Duration(10+(rand.Float32()*50)) * time.Millisecond)
-	dm.Unlock()
+	dm.Unlock(context.Background())
 
 	dm.Lock(id, source)
 	time.Sleep(time.Duration(10+(rand.Float32()*50)) * time.Millisecond)
-	dm.Unlock()
+	dm.Unlock(context.Background())
 }
 
 // Test two locks for same resource, one succeeds, one fails (after timeout)
@@ -108,7 +108,7 @@ func TestTwoSimultaneousLocksForSameResource(t *testing.T) {
 		time.Sleep(5 * testDrwMutexAcquireTimeout)
 		// fmt.Println("Unlocking dm1")
 
-		dm1st.Unlock()
+		dm1st.Unlock(context.Background())
 	}()
 
 	dm2nd.Lock(id, source)
@@ -116,7 +116,7 @@ func TestTwoSimultaneousLocksForSameResource(t *testing.T) {
 	// fmt.Printf("2nd lock obtained after 1st lock is released\n")
 	time.Sleep(testDrwMutexRefreshCallTimeout * 2)
 
-	dm2nd.Unlock()
+	dm2nd.Unlock(context.Background())
 }
 
 // Test three locks for same resource, one succeeds, one fails (after timeout)
@@ -134,7 +134,7 @@ func TestThreeSimultaneousLocksForSameResource(t *testing.T) {
 		time.Sleep(2 * testDrwMutexAcquireTimeout)
 		// fmt.Println("Unlocking dm1")
 
-		dm1st.Unlock()
+		dm1st.Unlock(context.Background())
 	}()
 	expect += 2 * testDrwMutexAcquireTimeout
 
@@ -151,7 +151,7 @@ func TestThreeSimultaneousLocksForSameResource(t *testing.T) {
 			time.Sleep(2 * testDrwMutexAcquireTimeout)
 			// fmt.Println("Unlocking dm2")
 
-			dm2nd.Unlock()
+			dm2nd.Unlock(context.Background())
 		}()
 
 		dm3rd.Lock(id, source)
@@ -159,7 +159,7 @@ func TestThreeSimultaneousLocksForSameResource(t *testing.T) {
 		// fmt.Printf("3rd lock obtained after 1st & 2nd locks are released\n")
 		time.Sleep(testDrwMutexRefreshCallTimeout)
 
-		dm3rd.Unlock()
+		dm3rd.Unlock(context.Background())
 	}()
 	expect += 2*testDrwMutexAcquireTimeout + testDrwMutexRefreshCallTimeout
 
@@ -173,7 +173,7 @@ func TestThreeSimultaneousLocksForSameResource(t *testing.T) {
 			time.Sleep(2 * testDrwMutexAcquireTimeout)
 			// fmt.Println("Unlocking dm3")
 
-			dm3rd.Unlock()
+			dm3rd.Unlock(context.Background())
 		}()
 
 		dm2nd.Lock(id, source)
@@ -181,7 +181,7 @@ func TestThreeSimultaneousLocksForSameResource(t *testing.T) {
 		// fmt.Printf("2nd lock obtained after 1st & 3rd locks are released\n")
 		time.Sleep(testDrwMutexRefreshCallTimeout)
 
-		dm2nd.Unlock()
+		dm2nd.Unlock(context.Background())
 	}()
 	expect += 2*testDrwMutexAcquireTimeout + testDrwMutexRefreshCallTimeout
 
@@ -201,8 +201,8 @@ func TestTwoSimultaneousLocksForDifferentResources(t *testing.T) {
 
 	dm1.Lock(id, source)
 	dm2.Lock(id, source)
-	dm1.Unlock()
-	dm2.Unlock()
+	dm1.Unlock(context.Background())
+	dm2.Unlock(context.Background())
 }
 
 // Test refreshing lock - refresh should always return true
@@ -230,7 +230,7 @@ func TestSuccessfulLockRefresh(t *testing.T) {
 	}
 
 	// Should be safe operation in all cases
-	dm.Unlock()
+	dm.Unlock(context.Background())
 }
 
 // Test canceling context while quorum servers report lock not found
@@ -267,7 +267,7 @@ func TestFailedRefreshLock(t *testing.T) {
 	}
 
 	// Should be safe operation in all cases
-	dm.Unlock()
+	dm.Unlock(context.Background())
 }
 
 // Test Unlock should not timeout
@@ -290,7 +290,9 @@ func TestUnlockShouldNotTimeout(t *testing.T) {
 
 	unlockReturned := make(chan struct{}, 1)
 	go func() {
-		dm.Unlock()
+		ctx, cancel := context.WithTimeout(context.Background(), 500*time.Millisecond)
+		defer cancel()
+		dm.Unlock(ctx)
 		unlockReturned <- struct{}{}
 	}()
 
@@ -308,7 +310,7 @@ func TestUnlockShouldNotTimeout(t *testing.T) {
 func HammerMutex(m *DRWMutex, loops int, cdone chan bool) {
 	for i := 0; i < loops; i++ {
 		m.Lock(id, source)
-		m.Unlock()
+		m.Unlock(context.Background())
 	}
 	cdone <- true
 }
@@ -340,7 +342,7 @@ func BenchmarkMutexUncontended(b *testing.B) {
 		mu := PaddedMutex{NewDRWMutex(ds, "")}
 		for pb.Next() {
 			mu.Lock(id, source)
-			mu.Unlock()
+			mu.Unlock(context.Background())
 		}
 	})
 }
@@ -357,7 +359,7 @@ func benchmarkMutex(b *testing.B, slack, work bool) {
 		foo := 0
 		for pb.Next() {
 			mu.Lock(id, source)
-			mu.Unlock()
+			mu.Unlock(context.Background())
 			if work {
 				for i := 0; i < 100; i++ {
 					foo *= 2
@@ -406,7 +408,7 @@ func BenchmarkMutexNoSpin(b *testing.B) {
 				m.Lock(id, source)
 				acc0 -= 100
 				acc1 += 100
-				m.Unlock()
+				m.Unlock(context.Background())
 			} else {
 				for i := 0; i < len(data); i += 4 {
 					data[i]++
@@ -438,7 +440,7 @@ func BenchmarkMutexSpin(b *testing.B) {
 			m.Lock(id, source)
 			acc0 -= 100
 			acc1 += 100
-			m.Unlock()
+			m.Unlock(context.Background())
 			for i := 0; i < len(data); i += 4 {
 				data[i]++
 			}