Implement consistent logging across the application (#3368)

Co-authored-by: Nicolas Dorseuil <nicolas@gitbook.io>
This commit is contained in:
conico974
2025-07-11 10:36:03 +02:00
committed by GitHub
parent 0a8dd67541
commit e38caf78ff
15 changed files with 249 additions and 253 deletions
@@ -16,7 +16,8 @@
"env": {
"dev": {
"vars": {
"STAGE": "dev"
"STAGE": "dev",
"OPEN_NEXT_REQUEST_ID_HEADER": "true"
},
"r2_buckets": [
{
@@ -84,6 +85,9 @@
}
},
"staging": {
"vars": {
"OPEN_NEXT_REQUEST_ID_HEADER": "true"
},
"r2_buckets": [
{
"binding": "NEXT_INC_CACHE_R2_BUCKET",
@@ -125,7 +129,8 @@
"vars": {
// This is a bit misleading, but it means that we can have 500 concurrent revalidations
// This means that we'll have up to 100 durable objects instance running at the same time
"MAX_REVALIDATE_CONCURRENCY": "100"
"MAX_REVALIDATE_CONCURRENCY": "100",
"OPEN_NEXT_REQUEST_ID_HEADER": "true"
},
"r2_buckets": [
{
@@ -21,7 +21,8 @@
"dev": {
"vars": {
"STAGE": "dev",
"NEXT_PRIVATE_DEBUG_CACHE": "true"
"NEXT_PRIVATE_DEBUG_CACHE": "true",
"OPEN_NEXT_REQUEST_ID_HEADER": "true"
},
"r2_buckets": [
{
@@ -85,7 +86,8 @@
"staging": {
"vars": {
"STAGE": "staging",
"WORKER_VERSION_ID": "TO_REPLACE"
"WORKER_VERSION_ID": "TO_REPLACE",
"OPEN_NEXT_REQUEST_ID_HEADER": "true"
},
"routes": [
{
@@ -153,7 +155,8 @@
// TODO: remove this once the issue is fixed
"DEBUG_CLOUDFLARE": "true",
"WORKER_VERSION_ID": "TO_REPLACE",
"STAGE": "production"
"STAGE": "production",
"OPEN_NEXT_REQUEST_ID_HEADER": "true"
},
"routes": [
{
+68 -95
View File
@@ -1,6 +1,4 @@
import { createHash } from 'node:crypto';
import { trace } from '@/lib/tracing';
import type {
CacheEntryType,
CacheValue,
@@ -34,41 +32,31 @@ class GitbookIncrementalCache implements IncrementalCache {
cacheType?: CacheType
): Promise<WithLastModified<CacheValue<CacheType>> | null> {
const cacheKey = this.getR2Key(key, cacheType);
return trace(
{
operation: 'openNextIncrementalCacheGet',
name: cacheKey,
},
async (span) => {
span.setAttribute('cacheType', cacheType ?? 'cache');
const r2 = getCloudflareContext().env[BINDING_NAME];
const localCache = await this.getCacheInstance();
if (!r2) throw new Error('No R2 bucket');
try {
// Check local cache first if available
const localCacheEntry = await localCache.match(this.getCacheUrlKey(cacheKey));
if (localCacheEntry) {
span.setAttribute('cacheHit', 'local');
const result = (await localCacheEntry.json()) as WithLastModified<
CacheValue<CacheType>
>;
return this.returnNullOn404(result);
}
const r2Object = await r2.get(cacheKey);
if (!r2Object) return null;
span.setAttribute('cacheHit', 'r2');
return this.returnNullOn404({
value: await r2Object.json(),
lastModified: r2Object.uploaded.getTime(),
});
} catch (e) {
console.error('Failed to get from cache', e);
return null;
}
const r2 = getCloudflareContext().env[BINDING_NAME];
const localCache = await this.getCacheInstance();
if (!r2) throw new Error('No R2 bucket');
try {
// Check local cache first if available
const localCacheEntry = await localCache.match(this.getCacheUrlKey(cacheKey));
if (localCacheEntry) {
const result = (await localCacheEntry.json()) as WithLastModified<
CacheValue<CacheType>
>;
return this.returnNullOn404(result);
}
);
const r2Object = await r2.get(cacheKey);
if (!r2Object) return null;
return this.returnNullOn404({
value: await r2Object.json(),
lastModified: r2Object.uploaded.getTime(),
});
} catch (e) {
console.error('Failed to get from cache', e);
return null;
}
}
//TODO: This is a workaround to handle 404 responses in the cache.
@@ -89,75 +77,60 @@ class GitbookIncrementalCache implements IncrementalCache {
cacheType?: CacheType
): Promise<void> {
const cacheKey = this.getR2Key(key, cacheType);
return trace(
{
operation: 'openNextIncrementalCacheSet',
name: cacheKey,
},
async (span) => {
span.setAttribute('cacheType', cacheType ?? 'cache');
const localCache = await this.getCacheInstance();
try {
await this.writeToR2(cacheKey, JSON.stringify(value));
const localCache = await this.getCacheInstance();
//TODO: Check if there is any places where we don't have tags
// Ideally we should always have tags, but in case we don't, we need to decide how to handle it
// For now we default to a build ID tag, which allow us to invalidate the cache in case something is wrong in this deployment
const tags = this.getTagsFromCacheEntry(value) ?? [
`build_id/${process.env.NEXT_BUILD_ID}`,
];
try {
await this.writeToR2(cacheKey, JSON.stringify(value));
// We consider R2 as the source of truth, so we update the local cache
// only after a successful R2 write
await localCache.put(
this.getCacheUrlKey(cacheKey),
new Response(
JSON.stringify({
value,
// Note: `Date.now()` returns the time of the last IO rather than the actual time.
// See https://developers.cloudflare.com/workers/reference/security-model/
lastModified: Date.now(),
}),
{
headers: {
// Cache-Control default to 30 minutes, will be overridden by `revalidate`
// In theory we should always get the `revalidate` value
'cache-control': `max-age=${value.revalidate ?? 60 * 30}`,
'cache-tag': tags.join(','),
},
}
)
);
} catch (e) {
console.error('Failed to set to cache', e);
}
}
);
//TODO: Check if there is any places where we don't have tags
// Ideally we should always have tags, but in case we don't, we need to decide how to handle it
// For now we default to a build ID tag, which allow us to invalidate the cache in case something is wrong in this deployment
const tags = this.getTagsFromCacheEntry(value) ?? [
`build_id/${process.env.NEXT_BUILD_ID}`,
];
// We consider R2 as the source of truth, so we update the local cache
// only after a successful R2 write
await localCache.put(
this.getCacheUrlKey(cacheKey),
new Response(
JSON.stringify({
value,
// Note: `Date.now()` returns the time of the last IO rather than the actual time.
// See https://developers.cloudflare.com/workers/reference/security-model/
lastModified: Date.now(),
}),
{
headers: {
// Cache-Control default to 30 minutes, will be overridden by `revalidate`
// In theory we should always get the `revalidate` value
'cache-control': `max-age=${value.revalidate ?? 60 * 30}`,
'cache-tag': tags.join(','),
},
}
)
);
} catch (e) {
console.error('Failed to set to cache', e);
}
}
async delete(key: string): Promise<void> {
const cacheKey = this.getR2Key(key);
return trace(
{
operation: 'openNextIncrementalCacheDelete',
name: cacheKey,
},
async () => {
const r2 = getCloudflareContext().env[BINDING_NAME];
const localCache = await this.getCacheInstance();
if (!r2) throw new Error('No R2 bucket');
try {
await r2.delete(cacheKey);
const r2 = getCloudflareContext().env[BINDING_NAME];
const localCache = await this.getCacheInstance();
if (!r2) throw new Error('No R2 bucket');
// Here again R2 is the source of truth, so we delete from local cache first
await localCache.delete(this.getCacheUrlKey(cacheKey));
} catch (e) {
console.error('Failed to delete from cache', e);
}
}
);
try {
await r2.delete(cacheKey);
// Here again R2 is the source of truth, so we delete from local cache first
await localCache.delete(this.getCacheUrlKey(cacheKey));
} catch (e) {
console.error('Failed to delete from cache', e);
}
}
async writeToR2(key: string, value: string): Promise<void> {
@@ -1,4 +1,3 @@
import { trace } from '@/lib/tracing';
import type { Queue } from '@opennextjs/aws/types/overrides.js';
import { getCloudflareContext } from '@opennextjs/cloudflare';
import doQueue from '@opennextjs/cloudflare/overrides/queue/do-queue';
@@ -6,9 +5,7 @@ import doQueue from '@opennextjs/cloudflare/overrides/queue/do-queue';
export default {
name: 'GitbookISRQueue',
send: async (msg) => {
return trace({ operation: 'gitbookISRQueueSend', name: msg.MessageBody.url }, async () => {
const { ctx } = getCloudflareContext();
ctx.waitUntil(doQueue.send(msg));
});
const { ctx } = getCloudflareContext();
ctx.waitUntil(doQueue.send(msg));
},
} satisfies Queue;
+3 -1
View File
@@ -1,9 +1,11 @@
import { getLogger } from '@/lib/logger';
import type { Queue } from '@opennextjs/aws/types/overrides.js';
export default {
name: 'GitbookISRQueue',
send: async (msg) => {
const logger = getLogger().subLogger('GitbookISRQueue');
// We should never reach this point in the server. If that's the case, we should log it.
console.warn('GitbookISRQueue: send called on server side, this should not happen.', msg);
logger.warn('send called on server side, this should not happen.', msg);
},
} satisfies Queue;
@@ -1,4 +1,4 @@
import { trace } from '@/lib/tracing';
import { getLogger } from '@/lib/logger';
import type { NextModeTagCache } from '@opennextjs/aws/types/overrides.js';
import doShardedTagCache from '@opennextjs/cloudflare/overrides/tag-cache/do-sharded-tag-cache';
import { softTagFilter } from '@opennextjs/cloudflare/overrides/tag-cache/tag-cache-filter';
@@ -23,59 +23,27 @@ export default {
getLastRevalidated: async (tags: string[]) => {
const tagsToCheck = tags.filter(softTagFilter);
if (tagsToCheck.length === 0) {
// If we reach here, it probably means that there is an issue that we'll need to address.
console.warn(
'getLastRevalidated - No valid tags to check for last revalidation, original tags:',
tags
);
return 0; // If no tags to check, return 0
}
return trace(
{
operation: 'gitbookTagCacheGetLastRevalidated',
name: tagsToCheck.join(', '),
},
async () => {
return await originalTagCache.getLastRevalidated(tagsToCheck);
}
);
return await originalTagCache.getLastRevalidated(tagsToCheck);
},
hasBeenRevalidated: async (tags: string[], lastModified?: number) => {
const tagsToCheck = tags.filter(softTagFilter);
if (tagsToCheck.length === 0) {
// If we reach here, it probably means that there is an issue that we'll need to address.
console.warn(
'hasBeenRevalidated - No valid tags to check for revalidation, original tags:',
tags
);
return false; // If no tags to check, return false
}
return trace(
{
operation: 'gitbookTagCacheHasBeenRevalidated',
name: tagsToCheck.join(', '),
},
async () => {
const result = await originalTagCache.hasBeenRevalidated(tagsToCheck, lastModified);
return result;
}
);
return await originalTagCache.hasBeenRevalidated(tagsToCheck, lastModified);
},
writeTags: async (tags: string[]) => {
return trace(
{
operation: 'gitbookTagCacheWriteTags',
name: tags.join(', '),
},
async () => {
const tagsToWrite = tags.filter(softTagFilter);
if (tagsToWrite.length === 0) {
console.warn('writeTags - No valid tags to write');
return; // If no tags to write, exit early
}
// Write only the filtered tags
await originalTagCache.writeTags(tagsToWrite);
}
);
const tagsToWrite = tags.filter(softTagFilter);
if (tagsToWrite.length === 0) {
const logger = getLogger().subLogger('gitbookTagCache');
logger.warn('writeTags - No valid tags to write');
return; // If no tags to write, exit early
}
// Write only the filtered tags
await originalTagCache.writeTags(tagsToWrite);
},
} satisfies NextModeTagCache;
@@ -1,5 +1,6 @@
import { type NextRequest, NextResponse } from 'next/server';
import { getLogger } from '@/lib/logger';
import { withVerifySignature } from '@/lib/routes';
import { revalidateTag } from 'next/cache';
@@ -12,6 +13,7 @@ interface JsonBody {
* The body should be a JSON with { tags: string[] }
*/
export async function POST(req: NextRequest) {
const logger = getLogger().subLogger('revalidate');
return withVerifySignature<JsonBody>(req, async (body) => {
if (!body.tags || !Array.isArray(body.tags)) {
return NextResponse.json(
@@ -23,8 +25,7 @@ export async function POST(req: NextRequest) {
}
body.tags.forEach((tag) => {
// biome-ignore lint/suspicious/noConsole: we want to log here
console.log(`Revalidating tag: ${tag}`);
logger.log(`Revalidating tag: ${tag}`);
revalidateTag(tag);
});
+3 -1
View File
@@ -4,6 +4,7 @@ import {
getDataOrNull,
throwIfDataError,
} from '@/lib/data';
import { getLogger } from '@/lib/logger';
import { getSiteStructureSections } from '@/lib/sites';
import type {
ChangeRequest,
@@ -290,10 +291,11 @@ export async function fetchSiteContextByIds(
return siteSpaceSettings;
}
const logger = getLogger().subLogger('fetchSiteContextByIds', {});
// We got the pointer from an API and customizations from another.
// It's possible that the two are unsynced leading to not found customizations for the space.
// It's better to fallback on customization of the site that displaying an error.
console.warn('Customization not found for site space', ids.siteSpace);
logger.warn('Customization not found for site space', ids.siteSpace);
}
return customizations.site;
+62 -88
View File
@@ -50,124 +50,98 @@ export function createDataFetcher(
// API that are tied to the token
//
getPublishedContentSite(params) {
return trace('getPublishedContentSite', () =>
getPublishedContentSite(input, {
organizationId: params.organizationId,
siteId: params.siteId,
siteShareKey: params.siteShareKey,
})
);
return getPublishedContentSite(input, {
organizationId: params.organizationId,
siteId: params.siteId,
siteShareKey: params.siteShareKey,
});
},
getSiteRedirectBySource(params) {
return trace('getSiteRedirectBySource', () =>
getSiteRedirectBySource(input, {
organizationId: params.organizationId,
siteId: params.siteId,
siteShareKey: params.siteShareKey,
source: params.source,
})
);
return getSiteRedirectBySource(input, {
organizationId: params.organizationId,
siteId: params.siteId,
siteShareKey: params.siteShareKey,
source: params.source,
});
},
getRevision(params) {
return trace('getRevision', () =>
getRevision(input, {
spaceId: params.spaceId,
revisionId: params.revisionId,
})
);
return getRevision(input, {
spaceId: params.spaceId,
revisionId: params.revisionId,
});
},
getRevisionPageByPath(params) {
return trace('getRevisionPageByPath', () =>
getRevisionPageByPath(input, {
spaceId: params.spaceId,
revisionId: params.revisionId,
path: params.path,
})
);
return getRevisionPageByPath(input, {
spaceId: params.spaceId,
revisionId: params.revisionId,
path: params.path,
});
},
getRevisionPageMarkdown(params) {
return trace('getRevisionPageMarkdown', () =>
getRevisionPageMarkdown(input, {
spaceId: params.spaceId,
revisionId: params.revisionId,
pageId: params.pageId,
})
);
return getRevisionPageMarkdown(input, {
spaceId: params.spaceId,
revisionId: params.revisionId,
pageId: params.pageId,
});
},
getRevisionPageDocument(params) {
return trace('getRevisionPageDocument', () =>
getRevisionPageDocument(input, {
spaceId: params.spaceId,
revisionId: params.revisionId,
pageId: params.pageId,
})
);
return getRevisionPageDocument(input, {
spaceId: params.spaceId,
revisionId: params.revisionId,
pageId: params.pageId,
});
},
getLatestOpenAPISpecVersionContent(params) {
return trace('getLatestOpenAPISpecVersionContent', () =>
getLatestOpenAPISpecVersionContent(input, {
organizationId: params.organizationId,
slug: params.slug,
})
);
return getLatestOpenAPISpecVersionContent(input, {
organizationId: params.organizationId,
slug: params.slug,
});
},
getSpace(params) {
return trace('getSpace', () =>
getSpace(input, {
spaceId: params.spaceId,
shareKey: params.shareKey,
})
);
return getSpace(input, {
spaceId: params.spaceId,
shareKey: params.shareKey,
});
},
getChangeRequest(params) {
return trace('getChangeRequest', () =>
getChangeRequest(input, {
spaceId: params.spaceId,
changeRequestId: params.changeRequestId,
})
);
return getChangeRequest(input, {
spaceId: params.spaceId,
changeRequestId: params.changeRequestId,
});
},
getDocument(params) {
return trace('getDocument', () =>
getDocument(input, {
spaceId: params.spaceId,
documentId: params.documentId,
})
);
return getDocument(input, {
spaceId: params.spaceId,
documentId: params.documentId,
});
},
getComputedDocument(params) {
return trace('getComputedDocument', () =>
getComputedDocument(input, {
organizationId: params.organizationId,
spaceId: params.spaceId,
source: params.source,
seed: params.seed,
})
);
return getComputedDocument(input, {
organizationId: params.organizationId,
spaceId: params.spaceId,
source: params.source,
seed: params.seed,
});
},
getEmbedByUrl(params) {
return trace('getEmbedByUrl', () =>
getEmbedByUrl(input, {
url: params.url,
spaceId: params.spaceId,
})
);
return getEmbedByUrl(input, {
url: params.url,
spaceId: params.spaceId,
});
},
searchSiteContent(params) {
return trace('searchSiteContent', () => searchSiteContent(input, params));
return searchSiteContent(input, params);
},
renderIntegrationUi(params) {
return trace('renderIntegrationUi', () =>
renderIntegrationUi(input, {
integrationName: params.integrationName,
request: params.request,
})
);
return renderIntegrationUi(input, {
integrationName: params.integrationName,
request: params.request,
});
},
getUserById(userId) {
return trace('getUserById', () => getUserById(input, { userId }));
return getUserById(input, { userId });
},
};
}
@@ -1,4 +1,5 @@
import { GITBOOK_IMAGE_RESIZE_URL } from '@/lib/env';
import { getLogger } from '@/lib/logger';
import type { CloudflareImageOptions } from './types';
import { copyImageResponse } from './utils';
@@ -24,8 +25,8 @@ export async function resizeImageWithCDNCgi(
resizeOptions
)}/${encodeURIComponent(input)}`;
// biome-ignore lint/suspicious/noConsole: this log is useful for debugging
console.log(`resize image using cdn-cgi: ${resizeURL}`);
const logger = getLogger().subLogger('imageResizing');
logger.log(`resize image using cdn-cgi: ${resizeURL}`);
return copyImageResponse(
await fetch(resizeURL, {
@@ -1,3 +1,4 @@
import { getLogger } from '@/lib/logger';
import type { CloudflareImageOptions } from './types';
import { copyImageResponse } from './utils';
@@ -13,8 +14,8 @@ export async function resizeImageWithCFFetch(
): Promise<Response> {
const { signal, ...resizeOptions } = options;
// biome-ignore lint/suspicious/noConsole: this log is useful for debugging
console.log(`resize image using cf-fetch: ${input}`);
const logger = getLogger().subLogger('imageResizing');
logger.log(`resize image using cf-fetch: ${input}`);
return copyImageResponse(
await fetch(input, {
@@ -1,4 +1,5 @@
import 'server-only';
import { getLogger } from '@/lib/logger';
import assertNever from 'assert-never';
import { GITBOOK_IMAGE_RESIZE_MODE } from '../../env';
import { SizableImageAction, checkIsSizableImageURL } from '../checkIsSizableImageURL';
@@ -34,7 +35,8 @@ export async function getImageSize(
height: json.original.height,
};
} catch (error) {
console.warn(`Error getting image size for ${input}:`, error);
const logger = getLogger().subLogger('imageResizing');
logger.warn(`Error getting image size for ${input}:`, error);
return null;
}
}
@@ -1,5 +1,6 @@
import 'server-only';
import { getLogger } from '@/lib/logger';
import fnv1a from '@sindresorhus/fnv1a';
import type { MaybePromise } from 'p-map';
import { assert } from 'ts-essentials';
@@ -33,10 +34,13 @@ export async function verifyImageSignature(
const generator = IMAGE_SIGNATURE_FUNCTIONS[version];
const generated = await generator(input);
// biome-ignore lint/suspicious/noConsole: we want to log the signature comparison
console.log(
`comparing image signature for "${input.url}" on identifier "${input.imagesContextId}": "${generated}" (expected) === "${signature}" (actual)`
);
const logger = getLogger().subLogger('imageResizing');
if (generated !== signature) {
// We only log if the signature does not match, to avoid logging useless information
logger.log(
`comparing image signature for "${input.url}" on identifier "${input.imagesContextId}": "${generated}" (expected) === "${signature}" (actual)`
);
}
return generated === signature;
}
+61
View File
@@ -0,0 +1,61 @@
export type LogLabelValue = string | number | undefined | boolean;
export type LogLabels = { [key: string]: LogLabelValue };
export type SubLoggerOptions = {
labels?: LogLabels;
};
export type LoggerOptions = SubLoggerOptions & {
requestId?: string;
};
const formatPrefix = (name: string, options: LoggerOptions) => {
const { labels } = options;
// The tail worker used for extracting the labels expect this format.
return `%${JSON.stringify(labels ?? {})}%[${name}]`;
};
/**
* Creates a logger with the given name, the logger will prefix all log messages with the name in square brackets.
* By default it will include a `requestId` label, and output labels in the log messages.
* Format of log messages will be:
* `%{"label1":"value1","label2":"value2"}%[loggerName] message...`
* @param name The name of the logger, which can be used to create a sub-logger.
* @param requestId An optional request ID to include in log messages for better traceability.
* @returns A logger object with methods for logging at different levels and creating sub-loggers.
*/
export const createLogger = (name: string, options: LoggerOptions) => {
const { requestId, labels } = options;
const finalOptions = { requestId, labels: { ...labels, requestId } };
return {
subLogger: (subName: string, options?: SubLoggerOptions) =>
createLogger(`${name}:${subName}`, {
requestId,
labels: { ...labels, ...(options?.labels ?? {}) },
}),
info: (...data: any[]) => console.info(formatPrefix(name, finalOptions), ...data),
warn: (...data: any[]) => console.warn(formatPrefix(name, finalOptions), ...data),
error: (...data: any[]) => console.error(formatPrefix(name, finalOptions), ...data),
debug: (...data: any[]) => console.debug(formatPrefix(name, finalOptions), ...data),
log: (...data: any[]) => console.log(formatPrefix(name, finalOptions), ...data),
};
};
export type GitbookLogger = ReturnType<typeof createLogger>;
const getRequestId = (fallbackRequestId?: string) => {
// We are in OpenNext and we should have access to the request ID.
if ((globalThis as any).__openNextAls) {
return (globalThis as any).__openNextAls.getStore()?.requestId;
}
return fallbackRequestId;
};
export const getLogger =
process.env.NEXT_RUNTIME === 'edge'
? () => createLogger('GBOV2', { requestId: getRequestId() })
: () =>
createLogger('GBOV2', {
requestId: getRequestId(Math.random().toString(36).substring(2, 15)),
});
+4 -2
View File
@@ -1,3 +1,5 @@
import { getLogger } from '@/lib/logger';
export interface TraceSpan {
setAttribute: (label: string, value: boolean | string | number) => void;
}
@@ -38,8 +40,8 @@ export async function trace<T>(
} finally {
if (process.env.SILENT !== 'true' && process.env.NODE_ENV !== 'development') {
const end = now();
// biome-ignore lint/suspicious/noConsole: we want to log performance data
console.log(
const logger = getLogger().subLogger(operation);
logger.log(
`trace ${completeName} ${traceError ? `failed with ${traceError.message}` : 'succeeded'} in ${end - start}ms`,
attributes
);