Skip to content

Commit 5d0042b

Browse files
vicbvicb
authored
add cache debug log (#911)
1 parent e0886d1 commit 5d0042b

File tree

8 files changed

+85
-33
lines changed

8 files changed

+85
-33
lines changed

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

Lines changed: 13 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,7 @@
11
import { DurableObject } from "cloudflare:workers";
22

3+
import { debugCache } from "../overrides/internal.js";
4+
35
export class DOShardedTagCache extends DurableObject<CloudflareEnv> {
46
sql: SqlStorage;
57

@@ -19,9 +21,10 @@ export class DOShardedTagCache extends DurableObject<CloudflareEnv> {
1921
...tags
2022
)
2123
.toArray();
22-
if (result.length === 0) return 0;
23-
// We only care about the most recent revalidation
24-
return result[0]?.time as number;
24+
25+
const timeMs = (result[0]?.time ?? 0) as number;
26+
debugCache("DOShardedTagCache", `getLastRevalidated tags=${tags} -> time=${timeMs}`);
27+
return timeMs;
2528
} catch (e) {
2629
console.error(e);
2730
// By default we don't want to crash here, so we return 0
@@ -30,18 +33,22 @@ export class DOShardedTagCache extends DurableObject<CloudflareEnv> {
3033
}
3134

3235
async hasBeenRevalidated(tags: string[], lastModified?: number): Promise<boolean> {
33-
return (
36+
const revalidated =
3437
this.sql
3538
.exec(
3639
`SELECT 1 FROM revalidations WHERE tag IN (${tags.map(() => "?").join(", ")}) AND revalidatedAt > ? LIMIT 1`,
3740
...tags,
3841
lastModified ?? Date.now()
3942
)
40-
.toArray().length > 0
41-
);
43+
.toArray().length > 0;
44+
45+
debugCache("DOShardedTagCache", `hasBeenRevalidated tags=${tags} -> revalidated=${revalidated}`);
46+
return revalidated;
4247
}
4348

4449
async writeTags(tags: string[], lastModified: number): Promise<void> {
50+
debugCache("DOShardedTagCache", `writeTags tags=${tags} time=${lastModified}`);
51+
4552
tags.forEach((tag) => {
4653
this.sql.exec(
4754
`INSERT OR REPLACE INTO revalidations (tag, revalidatedAt) VALUES (?, ?)`,

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

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -36,7 +36,7 @@ class KVIncrementalCache implements IncrementalCache {
3636
const kv = getCloudflareContext().env[BINDING_NAME];
3737
if (!kv) throw new IgnorableError("No KV Namespace");
3838

39-
debugCache(`Get ${key}`);
39+
debugCache("KVIncrementalCache", `get ${key}`);
4040

4141
try {
4242
const entry = await kv.get<IncrementalCacheEntry<CacheType>>(this.getKVKey(key, cacheType), "json");
@@ -66,7 +66,7 @@ class KVIncrementalCache implements IncrementalCache {
6666
const kv = getCloudflareContext().env[BINDING_NAME];
6767
if (!kv) throw new IgnorableError("No KV Namespace");
6868

69-
debugCache(`Set ${key}`);
69+
debugCache("KVIncrementalCache", `set ${key}`);
7070

7171
try {
7272
await kv.put(
@@ -89,7 +89,7 @@ class KVIncrementalCache implements IncrementalCache {
8989
const kv = getCloudflareContext().env[BINDING_NAME];
9090
if (!kv) throw new IgnorableError("No KV Namespace");
9191

92-
debugCache(`Delete ${key}`);
92+
debugCache("KVIncrementalCache", `delete ${key}`);
9393

9494
try {
9595
// Only cache that gets deleted is the ISR/SSG cache.

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

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -33,7 +33,7 @@ class R2IncrementalCache implements IncrementalCache {
3333
const r2 = getCloudflareContext().env[BINDING_NAME];
3434
if (!r2) throw new IgnorableError("No R2 bucket");
3535

36-
debugCache(`Get ${key}`);
36+
debugCache("R2IncrementalCache", `get ${key}`);
3737

3838
try {
3939
const r2Object = await r2.get(this.getR2Key(key, cacheType));
@@ -57,7 +57,7 @@ class R2IncrementalCache implements IncrementalCache {
5757
const r2 = getCloudflareContext().env[BINDING_NAME];
5858
if (!r2) throw new IgnorableError("No R2 bucket");
5959

60-
debugCache(`Set ${key}`);
60+
debugCache("R2IncrementalCache", `set ${key}`);
6161

6262
try {
6363
await r2.put(this.getR2Key(key, cacheType), JSON.stringify(value));
@@ -70,7 +70,7 @@ class R2IncrementalCache implements IncrementalCache {
7070
const r2 = getCloudflareContext().env[BINDING_NAME];
7171
if (!r2) throw new IgnorableError("No R2 bucket");
7272

73-
debugCache(`Delete ${key}`);
73+
debugCache("R2IncrementalCache", `delete ${key}`);
7474

7575
try {
7676
await r2.delete(this.getR2Key(key));

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

Lines changed: 7 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -105,8 +105,9 @@ class RegionalCache implements IncrementalCache {
105105

106106
// Check for a cached entry as this will be faster than the store response.
107107
const cachedResponse = await cache.match(urlKey);
108+
108109
if (cachedResponse) {
109-
debugCache("Get - cached response");
110+
debugCache("RegionalCache", `get ${key} -> cached response`);
110111

111112
// Re-fetch from the store and update the regional cache in the background.
112113
// Note: this is only useful when the Cache API is not purged automatically.
@@ -134,6 +135,8 @@ class RegionalCache implements IncrementalCache {
134135
const { value, lastModified } = rawEntry ?? {};
135136
if (!value || typeof lastModified !== "number") return null;
136137

138+
debugCache("RegionalCache", `get ${key} -> put to cache`);
139+
137140
// Update the locale cache after retrieving from the store.
138141
getCloudflareContext().ctx.waitUntil(
139142
this.putToCache({ key, cacheType, entry: { value, lastModified } })
@@ -152,6 +155,8 @@ class RegionalCache implements IncrementalCache {
152155
cacheType?: CacheType
153156
): Promise<void> {
154157
try {
158+
debugCache("RegionalCache", `set ${key}`);
159+
155160
await this.store.set(key, value, cacheType);
156161

157162
await this.putToCache({
@@ -170,6 +175,7 @@ class RegionalCache implements IncrementalCache {
170175
}
171176

172177
async delete(key: string): Promise<void> {
178+
debugCache("RegionalCache", `delete ${key}`);
173179
try {
174180
await this.store.delete(key);
175181

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

Lines changed: 8 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -30,7 +30,7 @@ class StaticAssetsIncrementalCache implements IncrementalCache {
3030
const assets = getCloudflareContext().env.ASSETS;
3131
if (!assets) throw new IgnorableError("No Static Assets");
3232

33-
debugCache(`Get ${key}`);
33+
debugCache("StaticAssetsIncrementalCache", `get ${key}`);
3434

3535
try {
3636
const response = await assets.fetch(this.getAssetUrl(key, cacheType));
@@ -49,12 +49,16 @@ class StaticAssetsIncrementalCache implements IncrementalCache {
4949
}
5050
}
5151

52-
async set(): Promise<void> {
53-
error("Failed to set to read-only cache");
52+
async set<CacheType extends CacheEntryType = "cache">(
53+
key: string,
54+
_value: CacheValue<CacheType>,
55+
cacheType?: CacheType
56+
): Promise<void> {
57+
error(`StaticAssetsIncrementalCache: Failed to set to read-only cache key=${key} type=${cacheType}`);
5458
}
5559

5660
async delete(): Promise<void> {
57-
error("Failed to delete from read-only cache");
61+
error("StaticAssetsIncrementalCache: Failed to delete from read-only cache");
5862
}
5963

6064
protected getAssetUrl(key: string, cacheType?: CacheEntryType): string {

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

Lines changed: 14 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -23,9 +23,9 @@ export class D1NextModeTagCache implements NextModeTagCache {
2323
.bind(...tags.map((tag) => this.getCacheKey(tag)))
2424
.run();
2525

26-
if (result.results.length === 0) return 0;
27-
// We only care about the most recent revalidation
28-
return (result.results[0]?.time ?? 0) as number;
26+
const timeMs = (result.results[0]?.time ?? 0) as number;
27+
debugCache("D1NextModeTagCache", `getLastRevalidated tags=${tags} -> ${timeMs}`);
28+
return timeMs;
2929
} catch (e) {
3030
// By default we don't want to crash here, so we return false
3131
// We still log the error though so we can debug it
@@ -45,7 +45,12 @@ export class D1NextModeTagCache implements NextModeTagCache {
4545
.bind(...tags.map((tag) => this.getCacheKey(tag)), lastModified ?? Date.now())
4646
.raw();
4747

48-
return result.length > 0;
48+
const revalidated = result.length > 0;
49+
debugCache(
50+
"D1NextModeTagCache",
51+
`hasBeenRevalidated tags=${tags} at=${lastModified} -> ${revalidated}`
52+
);
53+
return revalidated;
4954
} catch (e) {
5055
error(e);
5156
// By default we don't want to crash here, so we return false
@@ -58,14 +63,18 @@ export class D1NextModeTagCache implements NextModeTagCache {
5863
const { isDisabled, db } = this.getConfig();
5964
if (isDisabled || tags.length === 0) return Promise.resolve();
6065

66+
const nowMs = Date.now();
67+
6168
await db.batch(
6269
tags.map((tag) =>
6370
db
6471
.prepare(`INSERT INTO revalidations (tag, revalidatedAt) VALUES (?, ?)`)
65-
.bind(this.getCacheKey(tag), Date.now())
72+
.bind(this.getCacheKey(tag), nowMs)
6673
)
6774
);
6875

76+
debugCache("D1NextModeTagCache", `writeTags tags=${tags} time=${nowMs}`);
77+
6978
// TODO: See https://github.com/opennextjs/opennextjs-aws/issues/986
7079
if (isPurgeCacheEnabled()) {
7180
await purgeCacheByTags(tags);

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

Lines changed: 23 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -140,7 +140,9 @@ class ShardedDOTagCache implements NextModeTagCache {
140140
const cachedValue = await this.getFromRegionalCache({ doId, tags });
141141
// If all the value were found in the regional cache, we can just return the max value
142142
if (cachedValue.length === tags.length) {
143-
return Math.max(...cachedValue.map((item) => item.time));
143+
const timeMs = Math.max(...cachedValue.map((item) => item.time as number));
144+
debugCache("ShardedDOTagCache", `getLastRevalidated tags=${tags} -> ${timeMs} (regional cache)`);
145+
return timeMs;
144146
}
145147
// Otherwise we need to check the durable object on the ones that were not found in the cache
146148
const filteredTags = deduplicatedTags.filter(
@@ -150,12 +152,13 @@ class ShardedDOTagCache implements NextModeTagCache {
150152
const stub = this.getDurableObjectStub(doId);
151153
const lastRevalidated = await stub.getLastRevalidated(filteredTags);
152154

153-
const result = Math.max(...cachedValue.map((item) => item.time), lastRevalidated);
155+
const timeMs = Math.max(...cachedValue.map((item) => item.time), lastRevalidated);
154156

155157
// We then need to populate the regional cache with the missing tags
156158
getCloudflareContext().ctx.waitUntil(this.putToRegionalCache({ doId, tags }, stub));
157159

158-
return result;
160+
debugCache("ShardedDOTagCache", `getLastRevalidated tags=${tags} -> ${timeMs}`);
161+
return timeMs;
159162
})
160163
);
161164
return Math.max(...shardedTagRevalidationOutcomes);
@@ -187,6 +190,11 @@ class ShardedDOTagCache implements NextModeTagCache {
187190
});
188191

189192
if (cacheHasBeenRevalidated) {
193+
debugCache(
194+
"ShardedDOTagCache",
195+
`hasBeenRevalidated tags=${tags} at=${lastModified} -> true (regional cache)`
196+
);
197+
190198
return true;
191199
}
192200
const stub = this.getDurableObjectStub(doId);
@@ -200,6 +208,11 @@ class ShardedDOTagCache implements NextModeTagCache {
200208
);
201209
}
202210

211+
debugCache(
212+
"ShardedDOTagCache",
213+
`hasBeenRevalidated tags=${tags} at=${lastModified} -> ${_hasBeenRevalidated}`
214+
);
215+
203216
return _hasBeenRevalidated;
204217
})
205218
);
@@ -219,12 +232,16 @@ class ShardedDOTagCache implements NextModeTagCache {
219232
public async writeTags(tags: string[]): Promise<void> {
220233
const { isDisabled } = this.getConfig();
221234
if (isDisabled) return;
222-
const shardedTagGroups = this.groupTagsByDO({ tags, generateAllReplicas: true });
235+
223236
// We want to use the same revalidation time for all tags
224-
const currentTime = Date.now();
237+
const nowMs = Date.now();
238+
239+
debugCache("ShardedDOTagCache", `writeTags tags=${tags} time=${nowMs}`);
240+
241+
const shardedTagGroups = this.groupTagsByDO({ tags, generateAllReplicas: true });
225242
await Promise.all(
226243
shardedTagGroups.map(async ({ doId, tags }) => {
227-
await this.performWriteTagsWithRetry(doId, tags, currentTime);
244+
await this.performWriteTagsWithRetry(doId, tags, nowMs);
228245
})
229246
);
230247

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

Lines changed: 14 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -2,7 +2,7 @@ import { error } from "@opennextjs/aws/adapters/logger.js";
22
import type { NextModeTagCache } from "@opennextjs/aws/types/overrides.js";
33

44
import { getCloudflareContext } from "../../cloudflare-context.js";
5-
import { FALLBACK_BUILD_ID, isPurgeCacheEnabled, purgeCacheByTags } from "../internal.js";
5+
import { debugCache, FALLBACK_BUILD_ID, isPurgeCacheEnabled, purgeCacheByTags } from "../internal.js";
66

77
export const NAME = "kv-next-mode-tag-cache";
88

@@ -37,7 +37,9 @@ export class KVNextModeTagCache implements NextModeTagCache {
3737

3838
const revalidations = [...result.values()].filter((v) => v != null);
3939

40-
return revalidations.length === 0 ? 0 : Math.max(...revalidations);
40+
const timeMs = revalidations.length === 0 ? 0 : Math.max(...revalidations);
41+
debugCache("KVNextModeTagCache", `getLastRevalidated tags=${tags} -> time=${timeMs}`);
42+
return timeMs;
4143
} catch (e) {
4244
// By default we don't want to crash here, so we return false
4345
// We still log the error though so we can debug it
@@ -47,7 +49,12 @@ export class KVNextModeTagCache implements NextModeTagCache {
4749
}
4850

4951
async hasBeenRevalidated(tags: string[], lastModified?: number): Promise<boolean> {
50-
return (await this.getLastRevalidated(tags)) > (lastModified ?? Date.now());
52+
const revalidated = (await this.getLastRevalidated(tags)) > (lastModified ?? Date.now());
53+
debugCache(
54+
"KVNextModeTagCache",
55+
`hasBeenRevalidated tags=${tags} lastModified=${lastModified} -> ${revalidated}`
56+
);
57+
return revalidated;
5158
}
5259

5360
async writeTags(tags: string[]): Promise<void> {
@@ -56,14 +63,16 @@ export class KVNextModeTagCache implements NextModeTagCache {
5663
return Promise.resolve();
5764
}
5865

59-
const timeMs = String(Date.now());
66+
const nowMs = Date.now();
6067

6168
await Promise.all(
6269
tags.map(async (tag) => {
63-
await kv.put(this.getCacheKey(tag), timeMs);
70+
await kv.put(this.getCacheKey(tag), String(nowMs));
6471
})
6572
);
6673

74+
debugCache("KVNextModeTagCache", `writeTags tags=${tags} time=${nowMs}`);
75+
6776
// TODO: See https://github.com/opennextjs/opennextjs-aws/issues/986
6877
if (isPurgeCacheEnabled()) {
6978
await purgeCacheByTags(tags);

0 commit comments

Comments
 (0)