pkg/sqlutil: queryLogger must handle non-positive timoeouts

pkg/sqlutil/monitor.go

@@ -116,22 +116,37 @@ func (q *queryLogger) logError(err error) {
 	q.lggr.Errorw("SQL ERROR", "err", err, "sql", q)
 }
 
-// logTiming logs about context cancellation and timing after a query returns.
-// Queries which use their full timeout log critical level. More than 50% log error, and 10% warn.
+// logTiming logs about context errors and timing. Queries which use their full timeout log critical level. More than 50% log error, and 10% warn.
+// To be deferred to run after a query returns.
 func (q *queryLogger) logTiming(ctx context.Context, start time.Time) {
 	elapsed := time.Since(start)
-	if ctx.Err() != nil {
-		q.lggr.Debugw("SQL CONTEXT CANCELLED", "ms", elapsed.Milliseconds(), "err", ctx.Err(), "sql", q)
+
+	if err := ctx.Err(); err != nil {
+		if errors.Is(err, context.Canceled) {
+			q.lggr.Debugw("SQL Context Canceled", "ms", elapsed.Milliseconds(), "err", context.Cause(ctx), "sql", q)
+			return
+		} else if !errors.Is(err, context.DeadlineExceeded) {
+			q.lggr.Debugw("SQL Context Error", "ms", elapsed.Milliseconds(), "err", err, "sql", q)
+			return
+		}
+		q.lggr.Debugw("SQL Deadline Exceeded", "ms", elapsed.Milliseconds(), "err", err, "sql", q)
 	}
 
+	// Success or Deadline Exceeded, so calculate how much of the timeout was used.
 	deadline, ok := ctx.Deadline()
 	if !ok {
 		return
 	}
 	timeout := deadline.Sub(start)
 
-	pct := float64(elapsed) / float64(timeout)
-	pct *= 100
+	var pct float64 // percent of timeout used
+	if timeout > 0 {
+		pct = float64(elapsed) / float64(timeout)
+		pct *= 100
+	} else {
+		timeout = 0
+		pct = 100
+	}
 
 	kvs := []any{"ms", elapsed.Milliseconds(), "timeout", timeout.Milliseconds(), "percent", strconv.FormatFloat(pct, 'f', 1, 64), "sql", q}