util/admission: clarify context cancellation

Previously, whenever the AC code observed the context cancellation, it
reported it as "deadline expiring". This can be confusing when the
cancellation is caused by the caller explicitly canceling the context,
without using the deadline option of the context. This commit clarifies
the error as well as logging event when the context doesn't have the
deadline set.

Release note: None

Author: yuzefovich

pkg/util/admission/snapshot_queue.go

@@ -7,6 +7,7 @@ package admission
 
 import (
 	"context"
+	"fmt"
 	"sync"
 	"time"
 
@@ -196,11 +197,14 @@ func (s *SnapshotQueue) Admit(ctx context.Context, count int64) error {
 			item.mu.cancelled = true
 		}()
 		shouldRelease = false
-		deadline, _ := ctx.Deadline()
 		s.metrics.WaitDurations.RecordValue(waitDur)
+		var deadlineSubstring string
+		if deadline, hasDeadline := ctx.Deadline(); hasDeadline {
+			deadlineSubstring = fmt.Sprintf("deadline: %v, ", deadline)
+		}
 		return errors.Wrapf(ctx.Err(),
-			"context canceled while waiting in queue: deadline: %v, start: %v, dur: %v",
-			deadline, item.enqueueingTime, waitDur)
+			"context canceled while waiting in queue: %sstart: %v, dur: %v",
+			deadlineSubstring, item.enqueueingTime, waitDur)
 	case <-item.admitCh:
 		waitDur := timeutil.Since(item.enqueueingTime).Nanoseconds()
 		s.metrics.WaitDurations.RecordValue(waitDur)

pkg/util/admission/work_queue.go

@@ -714,10 +714,13 @@ func (q *WorkQueue) Admit(ctx context.Context, info WorkInfo) (enabled bool, err
 		// causing entering into the work queue to be delayed.
 		q.mu.Unlock()
 		q.metrics.incErrored(info.Priority)
-		deadline, _ := ctx.Deadline()
+		var deadlineSubstring string
+		if deadline, hasDeadline := ctx.Deadline(); hasDeadline {
+			deadlineSubstring = fmt.Sprintf("deadline: %v, ", deadline)
+		}
 		return true,
-			errors.Wrapf(ctx.Err(), "work %s context canceled before queueing: deadline: %v, now: %v",
-				q.workKind, deadline, startTime)
+			errors.Wrapf(ctx.Err(), "work %s context canceled before queueing: %snow: %v",
+				q.workKind, deadlineSubstring, startTime)
 	}
 	// Push onto heap(s).
 	ordering := fifoWorkOrdering
@@ -802,12 +805,18 @@ func (q *WorkQueue) Admit(ctx context.Context, info WorkInfo) (enabled bool, err
 		}
 		q.metrics.incErrored(info.Priority)
 		q.metrics.recordFinishWait(info.Priority, waitDur)
-		deadline, _ := ctx.Deadline()
 		recordAdmissionWorkQueueStats(span, waitDur, q.queueKind, info.Priority, true)
-		log.Eventf(ctx, "deadline expired, waited in %s queue with pri %s for %v", q.queueKind, admissionpb.WorkPriorityDict[info.Priority], waitDur)
+		if deadline, hasDeadline := ctx.Deadline(); hasDeadline {
+			log.Eventf(ctx, "deadline expired, waited in %s queue with pri %s for %v", q.queueKind, admissionpb.WorkPriorityDict[info.Priority], waitDur)
+			return true,
+				errors.Newf("deadline expired while waiting in queue: %s, pri: %s, deadline: %v, start: %v, dur: %v",
+					q.queueKind, admissionpb.WorkPriorityDict[info.Priority], deadline, startTime, waitDur)
+		}
+		// This is a pure context cancellation.
+		log.Eventf(ctx, "context canceled, waited in %s queue with pri %s for %v", q.queueKind, admissionpb.WorkPriorityDict[info.Priority], waitDur)
 		return true,
-			errors.Newf("deadline expired while waiting in queue: %s, pri: %s, deadline: %v, start: %v, dur: %v",
-				q.queueKind, admissionpb.WorkPriorityDict[info.Priority], deadline, startTime, waitDur)
+			errors.Newf("context canceled while waiting in queue: %s, pri: %s, start: %v, dur: %v",
+				q.queueKind, admissionpb.WorkPriorityDict[info.Priority], startTime, waitDur)
 	case chainID, ok := <-work.ch:
 		if !ok {
 			panic(errors.AssertionFailedf("channel should not be closed"))