Browse Source

Merge pull request #942 from RooVetGit/fix_retry_delay_bugs

Fix logic error in retry delays
Matt Rubens 10 months ago
parent
commit
a3bb0edeae
3 changed files with 132 additions and 19 deletions
  1. 5 0
      .changeset/moody-fans-build.md
  2. 9 15
      src/core/Cline.ts
  3. 118 4
      src/core/__tests__/Cline.test.ts

+ 5 - 0
.changeset/moody-fans-build.md

@@ -0,0 +1,5 @@
+---
+"roo-cline": patch
+---
+
+Fix logic error in retry delays

+ 9 - 15
src/core/Cline.ts

@@ -822,29 +822,21 @@ export class Cline {
 		const { mcpEnabled, alwaysApproveResubmit, requestDelaySeconds, rateLimitSeconds } =
 			(await this.providerRef.deref()?.getState()) ?? {}
 
-		let finalDelay = 0
+		let rateLimitDelay = 0
 
 		// Only apply rate limiting if this isn't the first request
 		if (this.lastApiRequestTime) {
 			const now = Date.now()
 			const timeSinceLastRequest = now - this.lastApiRequestTime
 			const rateLimit = rateLimitSeconds || 0
-			const rateLimitDelay = Math.max(0, rateLimit * 1000 - timeSinceLastRequest)
-			finalDelay = rateLimitDelay
+			rateLimitDelay = Math.ceil(Math.max(0, rateLimit * 1000 - timeSinceLastRequest) / 1000)
 		}
 
-		// Add exponential backoff delay for retries
-		if (retryAttempt > 0) {
-			const baseDelay = requestDelaySeconds || 5
-			const exponentialDelay = Math.ceil(baseDelay * Math.pow(2, retryAttempt)) * 1000
-			finalDelay = Math.max(finalDelay, exponentialDelay)
-		}
-
-		if (finalDelay > 0) {
+		// Only show rate limiting message if we're not retrying. If retrying, we'll include the delay there.
+		if (rateLimitDelay > 0 && retryAttempt === 0) {
 			// Show countdown timer
-			for (let i = Math.ceil(finalDelay / 1000); i > 0; i--) {
-				const delayMessage =
-					retryAttempt > 0 ? `Retrying in ${i} seconds...` : `Rate limiting for ${i} seconds...`
+			for (let i = rateLimitDelay; i > 0; i--) {
+				const delayMessage = `Rate limiting for ${i} seconds...`
 				await this.say("api_req_retry_delayed", delayMessage, undefined, true)
 				await delay(1000)
 			}
@@ -959,9 +951,11 @@ export class Cline {
 				const errorMsg = error.message ?? "Unknown error"
 				const baseDelay = requestDelaySeconds || 5
 				const exponentialDelay = Math.ceil(baseDelay * Math.pow(2, retryAttempt))
+				// Wait for the greater of the exponential delay or the rate limit delay
+				const finalDelay = Math.max(exponentialDelay, rateLimitDelay)
 
 				// Show countdown timer with exponential backoff
-				for (let i = exponentialDelay; i > 0; i--) {
+				for (let i = finalDelay; i > 0; i--) {
 					await this.say(
 						"api_req_retry_delayed",
 						`${errorMsg}\n\nRetry attempt ${retryAttempt + 1}\nRetrying in ${i} seconds...`,

+ 118 - 4
src/core/__tests__/Cline.test.ts

@@ -772,10 +772,8 @@ describe("Cline", () => {
 					false,
 				)
 
-				// Calculate expected delay calls based on exponential backoff
-				const exponentialDelay = Math.ceil(baseDelay * Math.pow(2, 1)) // retryAttempt = 1
-				const rateLimitDelay = baseDelay // Initial rate limit delay
-				const totalExpectedDelays = exponentialDelay + rateLimitDelay
+				// Calculate expected delay calls for countdown
+				const totalExpectedDelays = baseDelay // One delay per second for countdown
 				expect(mockDelay).toHaveBeenCalledTimes(totalExpectedDelays)
 				expect(mockDelay).toHaveBeenCalledWith(1000)
 
@@ -786,6 +784,122 @@ describe("Cline", () => {
 				)
 			})
 
+			it("should not apply retry delay twice", async () => {
+				const cline = new Cline(mockProvider, mockApiConfig, undefined, false, false, undefined, "test task")
+
+				// Mock delay to track countdown timing
+				const mockDelay = jest.fn().mockResolvedValue(undefined)
+				jest.spyOn(require("delay"), "default").mockImplementation(mockDelay)
+
+				// Mock say to track messages
+				const saySpy = jest.spyOn(cline, "say")
+
+				// Create a stream that fails on first chunk
+				const mockError = new Error("API Error")
+				const mockFailedStream = {
+					async *[Symbol.asyncIterator]() {
+						throw mockError
+					},
+					async next() {
+						throw mockError
+					},
+					async return() {
+						return { done: true, value: undefined }
+					},
+					async throw(e: any) {
+						throw e
+					},
+					async [Symbol.asyncDispose]() {
+						// Cleanup
+					},
+				} as AsyncGenerator<ApiStreamChunk>
+
+				// Create a successful stream for retry
+				const mockSuccessStream = {
+					async *[Symbol.asyncIterator]() {
+						yield { type: "text", text: "Success" }
+					},
+					async next() {
+						return { done: true, value: { type: "text", text: "Success" } }
+					},
+					async return() {
+						return { done: true, value: undefined }
+					},
+					async throw(e: any) {
+						throw e
+					},
+					async [Symbol.asyncDispose]() {
+						// Cleanup
+					},
+				} as AsyncGenerator<ApiStreamChunk>
+
+				// Mock createMessage to fail first then succeed
+				let firstAttempt = true
+				jest.spyOn(cline.api, "createMessage").mockImplementation(() => {
+					if (firstAttempt) {
+						firstAttempt = false
+						return mockFailedStream
+					}
+					return mockSuccessStream
+				})
+
+				// Set alwaysApproveResubmit and requestDelaySeconds
+				mockProvider.getState = jest.fn().mockResolvedValue({
+					alwaysApproveResubmit: true,
+					requestDelaySeconds: 3,
+				})
+
+				// Mock previous API request message
+				cline.clineMessages = [
+					{
+						ts: Date.now(),
+						type: "say",
+						say: "api_req_started",
+						text: JSON.stringify({
+							tokensIn: 100,
+							tokensOut: 50,
+							cacheWrites: 0,
+							cacheReads: 0,
+							request: "test request",
+						}),
+					},
+				]
+
+				// Trigger API request
+				const iterator = cline.attemptApiRequest(0)
+				await iterator.next()
+
+				// Verify delay is only applied for the countdown
+				const baseDelay = 3 // from requestDelaySeconds
+				const expectedDelayCount = baseDelay // One delay per second for countdown
+				expect(mockDelay).toHaveBeenCalledTimes(expectedDelayCount)
+				expect(mockDelay).toHaveBeenCalledWith(1000) // Each delay should be 1 second
+
+				// Verify countdown messages were only shown once
+				const retryMessages = saySpy.mock.calls.filter(
+					(call) => call[0] === "api_req_retry_delayed" && call[1]?.includes("Retrying in"),
+				)
+				expect(retryMessages).toHaveLength(baseDelay)
+
+				// Verify the retry message sequence
+				for (let i = baseDelay; i > 0; i--) {
+					expect(saySpy).toHaveBeenCalledWith(
+						"api_req_retry_delayed",
+						expect.stringContaining(`Retrying in ${i} seconds`),
+						undefined,
+						true,
+					)
+				}
+
+				// Verify final retry message
+				expect(saySpy).toHaveBeenCalledWith(
+					"api_req_retry_delayed",
+					expect.stringContaining("Retrying now"),
+					undefined,
+					false,
+				)
+			})
+
 			describe("loadContext", () => {
 				it("should process mentions in task and feedback tags", async () => {
 					const cline = new Cline(