From 052903bfb50de872ec13f35e0cd6c0df84b86291 Mon Sep 17 00:00:00 2001 From: Matt Rubens Date: Tue, 11 Feb 2025 10:52:39 -0500 Subject: [PATCH] Fix logic error in retry delays --- .changeset/moody-fans-build.md | 5 ++ src/core/Cline.ts | 24 +++--- src/core/__tests__/Cline.test.ts | 122 ++++++++++++++++++++++++++++++- 3 files changed, 132 insertions(+), 19 deletions(-) create mode 100644 .changeset/moody-fans-build.md diff --git a/.changeset/moody-fans-build.md b/.changeset/moody-fans-build.md new file mode 100644 index 00000000000..7f0a74a94d9 --- /dev/null +++ b/.changeset/moody-fans-build.md @@ -0,0 +1,5 @@ +--- +"roo-cline": patch +--- + +Fix logic error in retry delays diff --git a/src/core/Cline.ts b/src/core/Cline.ts index 58be39a11bc..b81a8f23fea 100644 --- a/src/core/Cline.ts +++ b/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...`, diff --git a/src/core/__tests__/Cline.test.ts b/src/core/__tests__/Cline.test.ts index 87fa034dec5..4031b2eb5e8 100644 --- a/src/core/__tests__/Cline.test.ts +++ b/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 + + // 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 + + // 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(