Traceable logs

.vscode/settings.json

@@ -132,6 +132,7 @@
     "superproperty",
     "supertypes",
     "tempserver",
+    "traceparent",
     "ts-nocheck",
     "twoslash",
     "typeof",

CHANGES.md

@@ -39,6 +39,9 @@ To be released.
      -  `new Service()` constructor now accepts `followedMessage` option.
      -  `Service.clone()` method now accepts `followedMessage` option.
 
+ -  Log messages now can be traced using [LogTape]'s [implicit contexts].
+    [[#118]]
+
  -  Added options for an AMQP driver to `fedify init` command.
 
      -  Added `amqp` value to the `-q`/`--message-queue` option of
@@ -51,6 +54,9 @@ To be released.
 
      -  `["fedify", "nodeinfo", "client"]`
 
+[implicit contexts]: https://logtape.org/manual/contexts#implicit-contexts
+[#118]: https://github.com/dahlia/fedify/issues/118
+
 
 Version 1.1.2
 -------------

cli/import_map.g.json

@@ -15,7 +15,7 @@
     "@fedify/fedify/x/hono": "../src/./x/hono.ts",
     "@hongminhee/aitertools": "jsr:@hongminhee/aitertools@^0.6.0",
     "@hugoalh/http-header-link": "jsr:@hugoalh/http-header-link@^1.0.2",
-    "@logtape/logtape": "jsr:@logtape/logtape@^0.6.2",
+    "@logtape/logtape": "jsr:@logtape/logtape@^0.7.1",
     "@phensley/language-tag": "npm:@phensley/language-tag@^1.9.0",
     "@std/assert": "jsr:@std/assert@^0.226.0",
     "@std/async": "jsr:@std/async@^1.0.5",

cli/import_map.json

@@ -9,7 +9,7 @@
     "@hongminhee/localtunnel": "jsr:@hongminhee/localtunnel@^0.2.0",
     "@jimp/core": "npm:@jimp/core@^1.6.0",
     "@jimp/wasm-webp": "npm:@jimp/wasm-webp@^1.6.0",
-    "@logtape/logtape": "jsr:@logtape/logtape@^0.6.2",
+    "@logtape/logtape": "jsr:@logtape/logtape@^0.7.1",
     "@poppanator/http-constants": "npm:@poppanator/http-constants@^1.1.1",
     "@std/dotenv": "jsr:@std/dotenv@^0.225.2",
     "@std/fs": "jsr:@std/fs@^0.229.3",

docs/manual/log.md

@@ -45,15 +45,27 @@ bun add @logtape/logtape
 Then, you can [`configure()`] the logger in the entry point of your app:
 
 ~~~~ typescript twoslash
+// @noErrors: 2307
+import { type ContextLocalStorage } from "@logtape/logtape";
+class AsyncLocalStorage<T> implements ContextLocalStorage<T> {
+  getStore(): T | undefined {
+    return undefined;
+  }
+  run<R>(store: T, callback: () => R): R {
+    return callback();
+  }
+}
+// ---cut-before---
+import { AsyncLocalStorage } from "node:async_hooks";
 import { configure, getConsoleSink } from "@logtape/logtape";
 
 await configure({
   sinks: { console: getConsoleSink() },
-  filters: {},
   loggers: [
     { category: "your-app", sinks: ["console"], level: "debug" },
     { category: "fedify",   sinks: ["console"], level: "error" },
   ],
+  contextLocalStorage: new AsyncLocalStorage(),
 });
 ~~~~
 
@@ -89,9 +101,18 @@ The `configure()` function takes an object with three properties:
     level can be one of the following: `"debug"`, `"info"`, `"warning"`,
     `"error"`, or `"fatal"`.
 
+`contextLocalStorage` (recommended)
+:   *This property is available since LogTape 0.7.0.*
+
+    An instance of [`AsyncLocalStorage`] that is used to store
+    [implicit contexts] of the log messages.  This is useful when you want to
+    trace the log messages in a specific context.
+
 [JSR]: https://jsr.io/@logtape/logtape
 [npm]: https://www.npmjs.com/package/@logtape/logtape
 [`configure()`]: https://jsr.io/@logtape/logtape/doc/~/configure
+[`AsyncLocalStorage`]: https://nodejs.org/api/async_context.html#class-asynclocalstorage
+[implicit contexts]: https://logtape.org/manual/contexts#implicit-contexts
 
 
 Categories
@@ -281,3 +302,84 @@ log messages.  The deprecation warnings are logged with the `"warning"` level
 in each category where the deprecated API is used.  If you want to see all
 deprecation warnings, you can set the log level to `"warning"` for the
 [`"fedify"` category](#fedify).
+
+
+Tracing
+-------
+
+*This feature is available since Fedify 1.2.0.*
+
+> [!CAUTION]
+> Traceable log messages rely on [implicit contexts] which was introduced in
+> LogTape 0.7.0.  If you don't configure `contextLocalStorage` in
+> [`configure()`], you cannot trace log messages.
+
+The most of log messages made by Fedify can be traced by either below two
+properties:
+
+`requestId`
+:   If the log message is made in the context of an HTTP request,
+    the `requestId` property is included in it.  The `requestId` is a unique
+    identifier for the HTTP request, which is derived from one of the following
+    headers:
+
+     -  [`X-Request-Id`]
+     -  `X-Correlation-Id`
+     -  [`Traceparent`]
+     -  Otherwise, the `requestId` is a unique string derived from
+        the current timestamp and the random number.
+
+`messageId`
+:   If the log message is made in the context of a background task,
+    the `messageId` property is included in it.  The `messageId` is a unique
+    identifier for the background task, which is a UUID. 
+
+When you want to trace log messages, first of all you need to use a sink that
+writes log messages as structured data.  For example, you can use
+a [file sink] with a [JSON Lines] formatter.  Oh, and don't forget to set
+`contextLocalStorage` in [`configure()`]!  To sum up, you can configure
+loggers like this:
+
+~~~~ typescript twoslash
+// @noErrors: 2307
+import { type ContextLocalStorage } from "@logtape/logtape";
+class AsyncLocalStorage<T> implements ContextLocalStorage<T> {
+  getStore(): T | undefined {
+    return undefined;
+  }
+  run<R>(store: T, callback: () => R): R {
+    return callback();
+  }
+}
+// ---cut-before---
+import { AsyncLocalStorage } from "node:async_hooks";
+import { type LogRecord, configure, getFileSink } from "@logtape/logtape";
+
+await configure({
+  sinks: {
+    file: getFileSink("fedify-logs.jsonld", {
+      formatter(record: LogRecord): string {
+        return JSON.stringify(record) + "\n";
+      }
+    })
+  },
+  loggers: [
+    { category: "fedify", sinks: ["file"], level: "info" },
+  ],
+  contextLocalStorage: new AsyncLocalStorage(),
+});
+~~~~
+
+If your loggers are configured like this, you can filter log messages by
+`requestId` or `messageId` in the log file.  For example, you can filter log
+messages by `requestId` using [`jq`]:
+
+~~~~ sh
+jq -r 'select(.properties.requestId == "your-request-id")' fedify-logs.jsonl
+~~~~
+
+[`X-Request-Id`]: https://http.dev/x-request-id
+[`Traceparent`]: https://www.w3.org/TR/trace-context/#traceparent-header
+[file sink]: https://logtape.org/manual/sinks#file-sink
+[JSON Lines]: https://jsonlines.org/
+[`jq`]: https://jqlang.github.io/jq/

docs/package.json

@@ -8,7 +8,7 @@
     "@fedify/redis": "0.2.0-dev.10",
     "@hono/node-server": "^1.12.2",
     "@js-temporal/polyfill": "^0.4.4",
-    "@logtape/logtape": "^0.5.1",
+    "@logtape/logtape": "^0.7.1",
     "@shikijs/vitepress-twoslash": "^1.17.6",
     "@teidesu/deno-types": "^1.46.3",
     "@types/amqplib": "^0.10.5",

src/deno.json

@@ -30,7 +30,7 @@
     "@fedify/fedify/x/hono": "./x/hono.ts",
     "@hongminhee/aitertools": "jsr:@hongminhee/aitertools@^0.6.0",
     "@hugoalh/http-header-link": "jsr:@hugoalh/http-header-link@^1.0.2",
-    "@logtape/logtape": "jsr:@logtape/logtape@^0.6.2",
+    "@logtape/logtape": "jsr:@logtape/logtape@^0.7.1",
     "@phensley/language-tag": "npm:@phensley/language-tag@^1.9.0",
     "@std/assert": "jsr:@std/assert@^0.226.0",
     "@std/async": "jsr:@std/async@^1.0.5",

src/federation/handler.ts

@@ -558,6 +558,7 @@ export async function handleInbox<TContextData>(
     await queue.enqueue(
       {
         type: "inbox",
+        id: crypto.randomUUID(),
         baseUrl: request.url,
         activity: json,
         identifier,

src/federation/middleware.ts

@@ -1,4 +1,4 @@
-import { getLogger } from "@logtape/logtape";
+import { getLogger, withContext } from "@logtape/logtape";
 import { handleNodeInfo, handleNodeInfoJrd } from "../nodeinfo/handler.ts";
 import {
   type AuthenticatedDocumentLoaderFactory,
@@ -388,12 +388,14 @@ export class FederationImpl<TContextData> implements Federation<TContextData> {
     }
   }
 
-  async #listenQueue(ctxData: TContextData, message: Message): Promise<void> {
-    if (message.type === "outbox") {
-      await this.#listenOutboxMessage(ctxData, message);
-    } else if (message.type === "inbox") {
-      await this.#listenInboxMessage(ctxData, message);
-    }
+  #listenQueue(ctxData: TContextData, message: Message): Promise<void> {
+    return withContext({ messageId: message.id }, async () => {
+      if (message.type === "outbox") {
+        await this.#listenOutboxMessage(ctxData, message);
+      } else if (message.type === "inbox") {
+        await this.#listenInboxMessage(ctxData, message);
+      }
+    });
   }
 
   async #listenOutboxMessage(
@@ -1739,6 +1741,7 @@ export class FederationImpl<TContextData> implements Federation<TContextData> {
     for (const inbox in inboxes) {
       const message: OutboxMessage = {
         type: "outbox",
+        id: crypto.randomUUID(),
         keys: keyJwkPairs,
         activity: jsonLd,
         activityId: activity.id?.href,
@@ -1757,24 +1760,27 @@ export class FederationImpl<TContextData> implements Federation<TContextData> {
     }
   }
 
-  async fetch(
+  fetch(
     request: Request,
     options: FederationFetchOptions<TContextData>,
   ): Promise<Response> {
-    const response = await this.#fetch(request, options);
-    const logger = getLogger(["fedify", "federation", "http"]);
-    const url = new URL(request.url);
-    const logTpl = "{method} {path}: {status}";
-    const values = {
-      method: request.method,
-      path: `${url.pathname}${url.search}`,
-      url: request.url,
-      status: response.status,
-    };
-    if (response.status >= 500) logger.error(logTpl, values);
-    else if (response.status >= 400) logger.warn(logTpl, values);
-    else logger.info(logTpl, values);
-    return response;
+    const requestId = getRequestId(request);
+    return withContext({ requestId }, async () => {
+      const response = await this.#fetch(request, options);
+      const logger = getLogger(["fedify", "federation", "http"]);
+      const url = new URL(request.url);
+      const logTpl = "{method} {path}: {status}";
+      const values = {
+        method: request.method,
+        path: `${url.pathname}${url.search}`,
+        url: request.url,
+        status: response.status,
+      };
+      if (response.status >= 500) logger.error(logTpl, values);
+      else if (response.status >= 400) logger.warn(logTpl, values);
+      else logger.info(logTpl, values);
+      return response;
+    });
   }
 
   async #fetch(
@@ -2906,6 +2912,7 @@ export class InboxContextImpl<TContextData> extends ContextImpl<TContextData>
     for (const inbox in inboxes) {
       const message: OutboxMessage = {
         type: "outbox",
+        id: crypto.randomUUID(),
         keys: keyJwkPairs,
         activity: this.activity,
         activityId,
@@ -2959,3 +2966,31 @@ function unauthorized(_request: Request): Response {
     },
   });
 }
+
+/**
+ * Generates or extracts a unique identifier for a request.
+ *
+ * This function first attempts to extract an existing request ID from standard
+ * tracing headers. If none exists, it generates a new one. The ID format is:
+ *
+ *  -  If from headers, uses the existing ID.
+ *  -  If generated, uses format `req_` followed by a base36 timestamp and
+ *     6 random chars.
+ *
+ * @param request The incoming HTTP request.
+ * @returns A string identifier unique to this request.
+ */
+function getRequestId(request: Request): string {
+  // First try to get existing trace ID from standard headers:
+  const traceId = request.headers.get("X-Request-Id") ||
+    request.headers.get("X-Correlation-Id") ||
+    request.headers.get("Traceparent")?.split("-")[1];
+  if (traceId != null) return traceId;
+  // Generate new ID if none exists:
+  // - Use timestamp for rough chronological ordering
+  // - Add random suffix for uniqueness within same millisecond
+  // - Prefix to distinguish from potential existing IDs
+  const timestamp = Date.now().toString(36);
+  const random = Math.random().toString(36).slice(2, 8);
+  return `req_${timestamp}${random}`;
+}

src/federation/queue.ts

@@ -7,6 +7,7 @@ export type Message = OutboxMessage | InboxMessage;
 
 export interface OutboxMessage {
   type: "outbox";
+  id: ReturnType<typeof crypto.randomUUID>;
   keys: SenderKeyJwkPair[];
   activity: unknown;
   activityId?: string;
@@ -18,6 +19,7 @@ export interface OutboxMessage {
 
 export interface InboxMessage {
   type: "inbox";
+  id: ReturnType<typeof crypto.randomUUID>;
   baseUrl: string;
   activity: unknown;
   started: string;