Repository: ponder-sh/ponder
Pull request #1130 (2024-10-03 19:12:10)

fix: progress >100%
## Description
This fixes a bug that would result in the progress showing > 100%. This was reported in the telegram a few times.

![telegram-cloud-photo-size-4-6039785064532919156-x](https://github.com/user-attachments/assets/74d79d66-834e-4360-969d-8bf726d66e1e)

## Diagnosis
This is a result of incorrect handling of `finalized` block refetching. The current logic is as follows:
- sync all blocks from `start` to `historicalLast`(minimum of `finalized` and `end`)
- check if `finalized` is stale (last fetched more than 5 mins ago)
- if not stale, enter realtime
- else, re-run this loop

However, `start` should not be used on iterations after the first, because this would lead to blocks being re-synced (they have already been synced on the first iteration) 

## Solution
The solution was to detect when `localHistoricalSyncGenerator` should skip blocks that have already been synced, by checking `syncProgress.current`. I validated this worked on the `project-uniswap-v3` example, which I was also able to recreate the original bug with.


Patch:
diff --git a/.changeset/tough-tigers-approve.md b/.changeset/tough-tigers-approve.md
new file mode 100644
index 00000000..0457a6d7
--- /dev/null
+++ b/.changeset/tough-tigers-approve.md
@@ -0,0 +1,5 @@
+---
+"@ponder/core": patch
+---
+
+Fixed a bug introduced in `0.6.0` that caused some apps to log progress greater than 100% and re-sync blocks unnecessarily.
diff --git a/.github/actions/setup/action.yml b/.github/actions/setup/action.yml
index 57bfbf65..3bfb2a6f 100644
--- a/.github/actions/setup/action.yml
+++ b/.github/actions/setup/action.yml
@@ -19,7 +19,7 @@ runs:
     - name: Set up foundry
       uses: foundry-rs/foundry-toolchain@v1
       with:
-        version: nightly
+        version: "nightly-d75318c9c7a1c6af5404fe96f63ca890dcdd588d"
 
     - name: Install dependencies
       shell: bash
diff --git a/packages/core/src/common/telemetry.ts b/packages/core/src/common/telemetry.ts
index 1a8a5340..3a0c0788 100644
--- a/packages/core/src/common/telemetry.ts
+++ b/packages/core/src/common/telemetry.ts
@@ -67,7 +67,11 @@ export function createTelemetry({
   logger,
 }: { options: Options; logger: Logger }) {
   if (options.telemetryDisabled) {
-    return { record: (_event: TelemetryEvent) => {}, kill: async () => {} };
+    return {
+      record: (_event: TelemetryEvent) => {},
+      flush: async () => {},
+      kill: async () => {},
+    };
   }
 
   const conf = new Conf<DeviceConf>({
@@ -208,6 +212,11 @@ export function createTelemetry({
     });
   }, HEARTBEAT_INTERVAL_MS);
 
+  // Note that this method is only used for testing.
+  const flush = async () => {
+    await queue.onIdle();
+  };
+
   const kill = async () => {
     clearInterval(heartbeatInterval);
     isKilled = true;
@@ -217,7 +226,7 @@ export function createTelemetry({
     await Promise.race([queue.onIdle(), wait(1_000)]);
   };
 
-  return { record, kill };
+  return { record, flush, kill };
 }
 
 async function getPackageManager() {
diff --git a/packages/core/src/sync/index.ts b/packages/core/src/sync/index.ts
index 34d7a2bd..41ccca1b 100644
--- a/packages/core/src/sync/index.ts
+++ b/packages/core/src/sync/index.ts
@@ -997,8 +997,20 @@ export async function* localHistoricalSyncGenerator({
   // Cursor to track progress.
   let fromBlock = hexToNumber(syncProgress.start.number);
 
-  // Handle a cache hit by fast forwarding and potentially exiting
-  if (syncProgress.cached !== undefined) {
+  /**
+   * Handle a cache hit by fast forwarding and potentially exiting.
+   * A cache hit can either be: (listed by priority)
+   *   1) recovering progress from earlier invocations with different `finalized` blocks
+   *   2) recovering progress from the interval cache
+   */
+  if (
+    syncProgress.current !== undefined &&
+    (syncProgress.cached === undefined ||
+      hexToNumber(syncProgress.current.number) >
+        hexToNumber(syncProgress.cached.number))
+  ) {
+    fromBlock = hexToNumber(syncProgress.current.number) + 1;
+  } else if (syncProgress.cached !== undefined) {
     // `getEvents` can make progress without calling `sync`, so immediately "yield"
     yield;
 
@@ -1026,7 +1038,7 @@ export async function* localHistoricalSyncGenerator({
      * time spent syncing ≈ time before indexing function feedback.
      */
     const interval: Interval = [
-      fromBlock,
+      Math.min(fromBlock, hexToNumber(historicalLast.number)),
       Math.min(fromBlock + estimateRange, hexToNumber(historicalLast.number)),
     ];
 


Test patch:
diff --git a/packages/core/src/common/telemetry.test.ts b/packages/core/src/common/telemetry.test.ts
index 7df18e90..4289e78f 100644
--- a/packages/core/src/common/telemetry.test.ts
+++ b/packages/core/src/common/telemetry.test.ts
@@ -3,9 +3,8 @@ import { mkdirSync } from "node:fs";
 import os from "node:os";
 import path from "node:path";
 import { createTelemetry } from "@/common/telemetry.js";
-import { wait } from "@/utils/wait.js";
 import { rimrafSync } from "rimraf";
-import { beforeEach, expect, test, vi } from "vitest";
+import { afterEach, beforeEach, expect, test, vi } from "vitest";
 import type { Common } from "./common.js";
 import { createLogger } from "./logger.js";
 
@@ -14,7 +13,10 @@ const fetchSpy = vi.fn();
 beforeEach(() => {
   fetchSpy.mockReset();
   vi.stubGlobal("fetch", fetchSpy);
-  return () => vi.unstubAllGlobals();
+});
+
+afterEach(() => {
+  vi.unstubAllGlobals();
 });
 
 beforeEach((context) => {
@@ -46,7 +48,7 @@ test("telemetry calls fetch with event body", async (context) => {
     properties: { duration_seconds: process.uptime() },
   });
 
-  await wait(0);
+  await telemetry.flush();
   await telemetry.kill();
 
   expect(fetchSpy).toHaveBeenCalledTimes(1);
@@ -77,10 +79,10 @@ test("telemetry does not submit events if telemetry is disabled", async (context
     properties: { duration_seconds: process.uptime() },
   });
 
-  await wait(0);
+  await telemetry.flush();
   await telemetry.kill();
 
-  expect(fetchSpy).toHaveBeenCalledTimes(0);
+  expect(fetchSpy).not.toHaveBeenCalled();
 });
 
 test("telemetry throws if event is submitted after kill", async (context) => {
@@ -96,7 +98,7 @@ test("telemetry throws if event is submitted after kill", async (context) => {
     });
   }
 
-  await wait(0);
+  await telemetry.flush();
   await telemetry.kill();
 
   expect(fetchSpy).toHaveBeenCalledTimes(5);
@@ -106,7 +108,35 @@ test("telemetry throws if event is submitted after kill", async (context) => {
     properties: { duration_seconds: process.uptime() },
   });
 
-  await wait(100);
+  await telemetry.flush();
 
   expect(fetchSpy).toHaveBeenCalledTimes(5);
 });
+
+test("kill resolves within 1 second even with slow events", async (context) => {
+  const telemetry = createTelemetry({
+    options: context.common.options,
+    logger: context.common.logger,
+  });
+
+  // Mock fetch to simulate a slow request
+  fetchSpy.mockImplementation(
+    () => new Promise((resolve) => setTimeout(resolve, 5000)),
+  );
+
+  // Record an event that will trigger the slow fetch
+  telemetry.record({
+    name: "lifecycle:heartbeat_send",
+    properties: { duration_seconds: process.uptime() },
+  });
+
+  const startTime = Date.now();
+  await telemetry.kill();
+  const endTime = Date.now();
+
+  const killDuration = endTime - startTime;
+  expect(killDuration).toBeLessThan(1100); // Allow a small buffer for execution time
+
+  // Ensure that fetch was called, but not completed
+  expect(fetchSpy).toHaveBeenCalledTimes(1);
+});