add cache debug log

packages/cloudflare/src/api/durable-objects/sharded-tag-cache.ts

@@ -1,5 +1,7 @@
 import { DurableObject } from "cloudflare:workers";
 
+import { debugCache } from "../overrides/internal.js";
+
 export class DOShardedTagCache extends DurableObject<CloudflareEnv> {
 	sql: SqlStorage;
 
@@ -19,9 +21,10 @@ export class DOShardedTagCache extends DurableObject<CloudflareEnv> {
 					...tags
 				)
 				.toArray();
-			if (result.length === 0) return 0;
-			// We only care about the most recent revalidation
-			return result[0]?.time as number;
+
+			const timeMs = (result[0]?.time ?? 0) as number;
+			debugCache("DOShardedTagCache", `getLastRevalidated tags=${tags} -> time=${timeMs}`);
+			return timeMs;
 		} catch (e) {
 			console.error(e);
 			// By default we don't want to crash here, so we return 0
@@ -30,18 +33,22 @@ export class DOShardedTagCache extends DurableObject<CloudflareEnv> {
 	}
 
 	async hasBeenRevalidated(tags: string[], lastModified?: number): Promise<boolean> {
-		return (
+		const revalidated =
 			this.sql
 				.exec(
 					`SELECT 1 FROM revalidations WHERE tag IN (${tags.map(() => "?").join(", ")}) AND revalidatedAt > ? LIMIT 1`,
 					...tags,
 					lastModified ?? Date.now()
 				)
-				.toArray().length > 0
-		);
+				.toArray().length > 0;
+
+		debugCache("DOShardedTagCache", `hasBeenRevalidated tags=${tags} -> revalidated=${revalidated}`);
+		return revalidated;
 	}
 
 	async writeTags(tags: string[], lastModified: number): Promise<void> {
+		debugCache("DOShardedTagCache", `writeTags tags=${tags} time=${lastModified}`);
+
 		tags.forEach((tag) => {
 			this.sql.exec(
 				`INSERT OR REPLACE INTO revalidations (tag, revalidatedAt) VALUES (?, ?)`,

packages/cloudflare/src/api/overrides/incremental-cache/kv-incremental-cache.ts

@@ -36,7 +36,7 @@ class KVIncrementalCache implements IncrementalCache {
 		const kv = getCloudflareContext().env[BINDING_NAME];
 		if (!kv) throw new IgnorableError("No KV Namespace");
 
-		debugCache(`Get ${key}`);
+		debugCache("KVIncrementalCache", `get ${key}`);
 
 		try {
 			const entry = await kv.get<IncrementalCacheEntry<CacheType>>(this.getKVKey(key, cacheType), "json");
@@ -66,7 +66,7 @@ class KVIncrementalCache implements IncrementalCache {
 		const kv = getCloudflareContext().env[BINDING_NAME];
 		if (!kv) throw new IgnorableError("No KV Namespace");
 
-		debugCache(`Set ${key}`);
+		debugCache("KVIncrementalCache", `set ${key}`);
 
 		try {
 			await kv.put(
@@ -89,7 +89,7 @@ class KVIncrementalCache implements IncrementalCache {
 		const kv = getCloudflareContext().env[BINDING_NAME];
 		if (!kv) throw new IgnorableError("No KV Namespace");
 
-		debugCache(`Delete ${key}`);
+		debugCache("KVIncrementalCache", `delete ${key}`);
 
 		try {
 			// Only cache that gets deleted is the ISR/SSG cache.

packages/cloudflare/src/api/overrides/incremental-cache/r2-incremental-cache.ts

@@ -33,7 +33,7 @@ class R2IncrementalCache implements IncrementalCache {
 		const r2 = getCloudflareContext().env[BINDING_NAME];
 		if (!r2) throw new IgnorableError("No R2 bucket");
 
-		debugCache(`Get ${key}`);
+		debugCache("R2IncrementalCache", `get ${key}`);
 
 		try {
 			const r2Object = await r2.get(this.getR2Key(key, cacheType));
@@ -57,7 +57,7 @@ class R2IncrementalCache implements IncrementalCache {
 		const r2 = getCloudflareContext().env[BINDING_NAME];
 		if (!r2) throw new IgnorableError("No R2 bucket");
 
-		debugCache(`Set ${key}`);
+		debugCache("R2IncrementalCache", `set ${key}`);
 
 		try {
 			await r2.put(this.getR2Key(key, cacheType), JSON.stringify(value));
@@ -70,7 +70,7 @@ class R2IncrementalCache implements IncrementalCache {
 		const r2 = getCloudflareContext().env[BINDING_NAME];
 		if (!r2) throw new IgnorableError("No R2 bucket");
 
-		debugCache(`Delete ${key}`);
+		debugCache("R2IncrementalCache", `delete ${key}`);
 
 		try {
 			await r2.delete(this.getR2Key(key));

packages/cloudflare/src/api/overrides/incremental-cache/regional-cache.ts

@@ -105,8 +105,9 @@ class RegionalCache implements IncrementalCache {
 
 			// Check for a cached entry as this will be faster than the store response.
 			const cachedResponse = await cache.match(urlKey);
+
 			if (cachedResponse) {
-				debugCache("Get - cached response");
+				debugCache("RegionalCache", `get ${key} -> cached response`);
 
 				// Re-fetch from the store and update the regional cache in the background.
 				// Note: this is only useful when the Cache API is not purged automatically.
@@ -134,6 +135,8 @@ class RegionalCache implements IncrementalCache {
 			const { value, lastModified } = rawEntry ?? {};
 			if (!value || typeof lastModified !== "number") return null;
 
+			debugCache("RegionalCache", `get ${key} -> put to cache`);
+
 			// Update the locale cache after retrieving from the store.
 			getCloudflareContext().ctx.waitUntil(
 				this.putToCache({ key, cacheType, entry: { value, lastModified } })
@@ -152,6 +155,8 @@ class RegionalCache implements IncrementalCache {
 		cacheType?: CacheType
 	): Promise<void> {
 		try {
+			debugCache("RegionalCache", `set ${key}`);
+
 			await this.store.set(key, value, cacheType);
 
 			await this.putToCache({
@@ -170,6 +175,7 @@ class RegionalCache implements IncrementalCache {
 	}
 
 	async delete(key: string): Promise<void> {
+		debugCache("RegionalCache", `delete ${key}`);
 		try {
 			await this.store.delete(key);
 

packages/cloudflare/src/api/overrides/incremental-cache/static-assets-incremental-cache.ts

@@ -30,7 +30,7 @@ class StaticAssetsIncrementalCache implements IncrementalCache {
 		const assets = getCloudflareContext().env.ASSETS;
 		if (!assets) throw new IgnorableError("No Static Assets");
 
-		debugCache(`Get ${key}`);
+		debugCache("StaticAssetsIncrementalCache", `get ${key}`);
 
 		try {
 			const response = await assets.fetch(this.getAssetUrl(key, cacheType));
@@ -50,11 +50,11 @@ class StaticAssetsIncrementalCache implements IncrementalCache {
 	}
 
 	async set(): Promise<void> {
-		error("Failed to set to read-only cache");
+		error("StaticAssetsIncrementalCache: Failed to set to read-only cache");
 	}
 
 	async delete(): Promise<void> {
-		error("Failed to delete from read-only cache");
+		error("StaticAssetsIncrementalCache: Failed to delete from read-only cache");
 	}
 
 	protected getAssetUrl(key: string, cacheType?: CacheEntryType): string {

packages/cloudflare/src/api/overrides/tag-cache/d1-next-tag-cache.ts

@@ -23,9 +23,9 @@ export class D1NextModeTagCache implements NextModeTagCache {
 				.bind(...tags.map((tag) => this.getCacheKey(tag)))
 				.run();
 
-			if (result.results.length === 0) return 0;
-			// We only care about the most recent revalidation
-			return (result.results[0]?.time ?? 0) as number;
+			const timeMs = (result.results[0]?.time ?? 0) as number;
+			debugCache("D1NextModeTagCache", `getLastRevalidated tags=${tags} -> ${timeMs}`);
+			return timeMs;
 		} catch (e) {
 			// By default we don't want to crash here, so we return false
 			// We still log the error though so we can debug it
@@ -45,7 +45,12 @@ export class D1NextModeTagCache implements NextModeTagCache {
 				.bind(...tags.map((tag) => this.getCacheKey(tag)), lastModified ?? Date.now())
 				.raw();
 
-			return result.length > 0;
+			const revalidated = result.length > 0;
+			debugCache(
+				"D1NextModeTagCache",
+				`hasBeenRevalidated tags=${tags} at=${lastModified} -> ${revalidated}`
+			);
+			return revalidated;
 		} catch (e) {
 			error(e);
 			// By default we don't want to crash here, so we return false
@@ -58,14 +63,18 @@ export class D1NextModeTagCache implements NextModeTagCache {
 		const { isDisabled, db } = this.getConfig();
 		if (isDisabled || tags.length === 0) return Promise.resolve();
 
+		const nowMs = Date.now();
+
 		await db.batch(
 			tags.map((tag) =>
 				db
 					.prepare(`INSERT INTO revalidations (tag, revalidatedAt) VALUES (?, ?)`)
-					.bind(this.getCacheKey(tag), Date.now())
+					.bind(this.getCacheKey(tag), nowMs)
 			)
 		);
 
+		debugCache("D1NextModeTagCache", `writeTags tags=${tags} time=${nowMs}`);
+
 		// TODO: See https://github.com/opennextjs/opennextjs-aws/issues/986
 		if (isPurgeCacheEnabled()) {
 			await purgeCacheByTags(tags);

packages/cloudflare/src/api/overrides/tag-cache/do-sharded-tag-cache.ts

@@ -140,7 +140,9 @@ class ShardedDOTagCache implements NextModeTagCache {
 					const cachedValue = await this.getFromRegionalCache({ doId, tags });
 					// If all the value were found in the regional cache, we can just return the max value
 					if (cachedValue.length === tags.length) {
-						return Math.max(...cachedValue.map((item) => item.time));
+						const timeMs = Math.max(...cachedValue.map((item) => item.time as number));
+						debugCache("ShardedDOTagCache", `getLastRevalidated tags=${tags} -> ${timeMs} (regional cache)`);
+						return timeMs;
 					}
 					// Otherwise we need to check the durable object on the ones that were not found in the cache
 					const filteredTags = deduplicatedTags.filter(
@@ -150,12 +152,13 @@ class ShardedDOTagCache implements NextModeTagCache {
 					const stub = this.getDurableObjectStub(doId);
 					const lastRevalidated = await stub.getLastRevalidated(filteredTags);
 
-					const result = Math.max(...cachedValue.map((item) => item.time), lastRevalidated);
+					const timeMs = Math.max(...cachedValue.map((item) => item.time), lastRevalidated);
 
 					// We then need to populate the regional cache with the missing tags
 					getCloudflareContext().ctx.waitUntil(this.putToRegionalCache({ doId, tags }, stub));
 
-					return result;
+					debugCache("ShardedDOTagCache", `getLastRevalidated tags=${tags} -> ${timeMs}`);
+					return timeMs;
 				})
 			);
 			return Math.max(...shardedTagRevalidationOutcomes);
@@ -187,6 +190,11 @@ class ShardedDOTagCache implements NextModeTagCache {
 					});
 
 					if (cacheHasBeenRevalidated) {
+						debugCache(
+							"ShardedDOTagCache",
+							`hasBeenRevalidated tags=${tags} at=${lastModified} -> true (regional cache)`
+						);
+
 						return true;
 					}
 					const stub = this.getDurableObjectStub(doId);
@@ -200,6 +208,11 @@ class ShardedDOTagCache implements NextModeTagCache {
 						);
 					}
 
+					debugCache(
+						"ShardedDOTagCache",
+						`hasBeenRevalidated tags=${tags} at=${lastModified} -> ${_hasBeenRevalidated}`
+					);
+
 					return _hasBeenRevalidated;
 				})
 			);
@@ -219,12 +232,16 @@ class ShardedDOTagCache implements NextModeTagCache {
 	public async writeTags(tags: string[]): Promise<void> {
 		const { isDisabled } = this.getConfig();
 		if (isDisabled) return;
-		const shardedTagGroups = this.groupTagsByDO({ tags, generateAllReplicas: true });
+
 		// We want to use the same revalidation time for all tags
-		const currentTime = Date.now();
+		const nowMs = Date.now();
+
+		debugCache("ShardedDOTagCache", `writeTags tags=${tags} time=${nowMs}`);
+
+		const shardedTagGroups = this.groupTagsByDO({ tags, generateAllReplicas: true });
 		await Promise.all(
 			shardedTagGroups.map(async ({ doId, tags }) => {
-				await this.performWriteTagsWithRetry(doId, tags, currentTime);
+				await this.performWriteTagsWithRetry(doId, tags, nowMs);
 			})
 		);
 

packages/cloudflare/src/api/overrides/tag-cache/kv-next-tag-cache.ts

@@ -2,7 +2,7 @@ import { error } from "@opennextjs/aws/adapters/logger.js";
 import type { NextModeTagCache } from "@opennextjs/aws/types/overrides.js";
 
 import { getCloudflareContext } from "../../cloudflare-context.js";
-import { FALLBACK_BUILD_ID, isPurgeCacheEnabled, purgeCacheByTags } from "../internal.js";
+import { debugCache, FALLBACK_BUILD_ID, isPurgeCacheEnabled, purgeCacheByTags } from "../internal.js";
 
 export const NAME = "kv-next-mode-tag-cache";
 
@@ -37,7 +37,9 @@ export class KVNextModeTagCache implements NextModeTagCache {
 
 			const revalidations = [...result.values()].filter((v) => v != null);
 
-			return revalidations.length === 0 ? 0 : Math.max(...revalidations);
+			const timeMs = revalidations.length === 0 ? 0 : Math.max(...revalidations);
+			debugCache("KVNextModeTagCache", `getLastRevalidated tags=${tags} -> time=${timeMs}`);
+			return timeMs;
 		} catch (e) {
 			// By default we don't want to crash here, so we return false
 			// We still log the error though so we can debug it
@@ -47,7 +49,12 @@ export class KVNextModeTagCache implements NextModeTagCache {
 	}
 
 	async hasBeenRevalidated(tags: string[], lastModified?: number): Promise<boolean> {
-		return (await this.getLastRevalidated(tags)) > (lastModified ?? Date.now());
+		const revalidated = (await this.getLastRevalidated(tags)) > (lastModified ?? Date.now());
+		debugCache(
+			"KVNextModeTagCache",
+			`hasBeenRevalidated tags=${tags} lastModified=${lastModified} -> ${revalidated}`
+		);
+		return revalidated;
 	}
 
 	async writeTags(tags: string[]): Promise<void> {
@@ -56,14 +63,16 @@ export class KVNextModeTagCache implements NextModeTagCache {
 			return Promise.resolve();
 		}
 
-		const timeMs = String(Date.now());
+		const nowMs = Date.now();
 
 		await Promise.all(
 			tags.map(async (tag) => {
-				await kv.put(this.getCacheKey(tag), timeMs);
+				await kv.put(this.getCacheKey(tag), String(nowMs));
 			})
 		);
 
+		debugCache("KVNextModeTagCache", `writeTags tags=${tags} time=${nowMs}`);
+
 		// TODO: See https://github.com/opennextjs/opennextjs-aws/issues/986
 		if (isPurgeCacheEnabled()) {
 			await purgeCacheByTags(tags);