Log messages in inbox/outbox

.vscode/settings.json

@@ -54,6 +54,7 @@
     "keypair",
     "langstr",
     "Lemmy",
+    "logtape",
     "lume",
     "lumocs",
     "metas",

deno.json

@@ -29,6 +29,7 @@
     "@fedify/fedify/x/hono": "./x/hono.ts",
     "@hongminhee/aitertools": "jsr:@hongminhee/aitertools@^0.6.0",
     "@js-temporal/polyfill": "npm:@js-temporal/polyfill@^0.4.4",
+    "@logtape/logtape": "jsr:@logtape/logtape@^0.2.1",
     "@phensley/language-tag": "npm:@phensley/language-tag@^1.8.0",
     "@std/assert": "jsr:@std/assert@^0.220.1",
     "@std/async/delay": "jsr:@std/async@^0.220.1/delay",

docs/.vitepress/config.mts

@@ -83,6 +83,7 @@ export default defineConfig({
           { text: "Pragmatics", link: "/manual/pragmatics.md" },
           { text: "Integration", link: "/manual/integration.md" },
           { text: "Testing", link: "/manual/test.md" },
+          { text: "Logging", link: "/manual/log.md" },
         ],
       },
       {

docs/manual.md

@@ -30,6 +30,7 @@ framework.
  -  [Pragmatics](./manual/pragmatics.md)
  -  [Integration](./manual/integration.md)
  -  [Testing](./manual/test.md)
+ -  [Logging](./manual/log.md)
 
 However, this manual is not a complete guide to the Fedify framework.
 In particular, you probably want to look up the [API reference] times to times,

docs/manual/log.md

@@ -0,0 +1,152 @@
+---
+description: >-
+  Logging is a useful tool for debugging your federated server app.  This
+  section explains how to enable logging in your federated server app.
+prev:
+  text: Testing
+  link: ./test.md
+next: false
+---
+
+Logging
+=======
+
+Fedify uses the [LogTape] package to log message.  You can enable logging in
+your federated server app by installing the `@logtape/logtape` package and
+configuring it in the entry point of your app.
+
+[LogTape]: https://github.com/dahlia/logtape
+
+
+Setting up LogTape
+------------------
+
+To enable logging in your federated server app, you need to install the
+`@logtape/logtape` package (available on both [JSR] and [npm]):
+
+::: code-group
+
+~~~~ sh [Deno]
+deno add @logtape/logtape
+~~~~
+
+~~~~ sh [Node.js]
+npm add @logtape/logtape
+~~~~
+
+~~~~ sh [Bun]
+bun add @logtape/logtape
+~~~~
+
+:::
+
+[JSR]: https://jsr.io/@logtape/logtape
+[npm]: https://www.npmjs.com/package/@logtape/logtape
+
+Then, you can `configure()` the logger in the entry point of your app:
+
+~~~~ typescript
+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" },
+  ],
+});
+~~~~
+
+The `configure()` function takes an object with three properties:
+
+`sinks` (mandatory)
+:   An object that maps sink names to sink instances.  In this example, we use
+    the `getConsoleSink()` function to get a console sink instance.
+
+`filters` (mandatory)
+:   An object that maps logger categories to filter functions.  In this example,
+    we use an empty object to disable filtering.
+
+`loggers` (mandatory)
+:   An array of logger configurations.  Each configuration is an object with
+    four properties:
+
+`loggers.category` (mandatory)
+:   The `category` property is an array of string or a string that specifies
+    the logger category.  If a string is given, it is treated as an array
+    with a single element.
+
+`loggers.sinks` (optional)
+:   The `sinks` property is an array of string that specifies the sink names
+    that the logger should use.
+
+`loggers.filters` (optional)
+:   The `filters` property is an array of string that specifies the filter
+    names that the logger should use.
+
+`loggers.level` (optional)
+:   The `level` property is a string that specifies the log level.  The log
+    level can be one of the following: `"trace"`, `"debug"`, `"info"`,
+    `"warning"`, `"error"`, or `"fatal"`.
+
+
+Categories
+----------
+
+> [!TIP]
+> A logger category is an array of strings that specifies the logger category.
+> The logger category is used to filter log messages, or to configure
+> the specific sink for the logger.  Since it's hierarchical, you can filter
+> out log messages by specifying a prefix of the logger category while
+> seeing log messages of a specific subcategory.
+>
+> Note that the logger category is case-sensitive.  A bare string is treated
+> as an array with a single element.
+
+Fedify uses the following logger categories:
+
+### `"fedify"`
+
+The `"fedify"` category is used for everything related to the Fedify library.
+
+### `["fedify", "federation"]`
+
+The `["fedify", "federation"]` category is used for logging federation-related
+messages.
+
+### `["fedify", "federation", "inbox"]`
+
+The `["fedify", "federation", "inbox"]` category is used for logging messages
+related to incoming activities.  When you cannot receive an activity, you can
+check the log messages in this category with the `"debug"` level.
+
+### `["fedify", "federation", "outbox"]`
+
+The `["fedify", "federation", "outbox"]` category is used for logging messages
+related to outgoing activities.  When you cannot send an activity, you can
+check the log messages in this category with the `"debug"` level.
+
+
+Sinks
+-----
+
+A sink is a destination where log messages are sent.  LogTape provides few
+built-in sinks:
+
+ -  [console sink]
+ -  [stream sink]
+ -  [file sink]
+ -  [rotating file sink]
+
+However, you can create your own sink by implementing the [`Sink`] interface,
+e.g., to send log messages to a database or a cloud service.
+
+For more information about sinks, see the [*Sinks* section] in the LogTape docs.
+
+[console sink]: https://github.com/dahlia/logtape?tab=readme-ov-file#console-sink
+[stream sink]: https://github.com/dahlia/logtape?tab=readme-ov-file#stream-sink
+[file sink]: https://github.com/dahlia/logtape?tab=readme-ov-file#file-sink
+[rotating file sink]: https://github.com/dahlia/logtape?tab=readme-ov-file#rotating-file-sink
+[`Sink`]: https://jsr.io/@logtape/logtape/doc/~/Sink
+[*Sinks* section]: https://github.com/dahlia/logtape?tab=readme-ov-file#sinks

docs/manual/test.md

@@ -6,7 +6,9 @@ description: >-
 prev:
   text: Integration
   link: ./integration.md
-next: false
+next:
+  text: Logging
+  link: ./log.md
 ---
 
 Testing

federation/handler.ts

@@ -1,4 +1,5 @@
 import { Temporal } from "@js-temporal/polyfill";
+import { getLogger } from "@logtape/logtape";
 import { accepts } from "@std/http/negotiation";
 import { doesActorOwnKey, verify } from "../httpsig/mod.ts";
 import type { DocumentLoader } from "../runtime/docloader.ts";
@@ -233,14 +234,21 @@ export async function handleInbox<TContextData>(
     onNotFound,
   }: InboxHandlerParameters<TContextData>,
 ): Promise<Response> {
-  if (actorDispatcher == null) return await onNotFound(request);
-  else if (handle != null) {
+  const logger = getLogger(["fedify", "federation", "inbox"]);
+  if (actorDispatcher == null) {
+    logger.error("Actor dispatcher is not set.", { handle });
+    return await onNotFound(request);
+  } else if (handle != null) {
     const key = await context.getActorKey(handle);
     const actor = await actorDispatcher(context, handle, key);
-    if (actor == null) return await onNotFound(request);
+    if (actor == null) {
+      logger.error("Actor {handle} not found.", { handle });
+      return await onNotFound(request);
+    }
   }
   const key = await verify(request, context.documentLoader);
   if (key == null) {
+    logger.error("Failed to verify the request signature.", { handle });
     const response = new Response("Failed to verify the request signature.", {
       status: 401,
       headers: { "Content-Type": "text/plain; charset=utf-8" },
@@ -250,8 +258,9 @@ export async function handleInbox<TContextData>(
   let json: unknown;
   try {
     json = await request.json();
-  } catch (e) {
-    await inboxErrorHandler?.(context, e);
+  } catch (error) {
+    logger.error("Failed to parse JSON:\n{error}", { handle, error });
+    await inboxErrorHandler?.(context, error);
     return new Response("Invalid JSON.", {
       status: 400,
       headers: { "Content-Type": "text/plain; charset=utf-8" },
@@ -260,8 +269,9 @@ export async function handleInbox<TContextData>(
   let activity: Activity;
   try {
     activity = await Activity.fromJsonLd(json, context);
-  } catch (e) {
-    await inboxErrorHandler?.(context, e);
+  } catch (error) {
+    logger.error("Failed to parse activity:\n{error}", { handle, json, error });
+    await inboxErrorHandler?.(context, error);
     return new Response("Invalid activity.", {
       status: 400,
       headers: { "Content-Type": "text/plain; charset=utf-8" },
@@ -273,6 +283,10 @@ export async function handleInbox<TContextData>(
   if (cacheKey != null) {
     const cached = await kv.get(cacheKey);
     if (cached === true) {
+      logger.debug("Activity {activityId} has already been processed.", {
+        activityId: activity.id?.href,
+        activity: json,
+      });
       return new Response(
         `Activity <${activity.id}> has already been processed.`,
         {
@@ -283,13 +297,18 @@ export async function handleInbox<TContextData>(
     }
   }
   if (activity.actorId == null) {
+    logger.error("Missing actor.", { activity: json });
     const response = new Response("Missing actor.", {
       status: 400,
       headers: { "Content-Type": "text/plain; charset=utf-8" },
     });
     return response;
   }
   if (!await doesActorOwnKey(activity, key, context.documentLoader)) {
+    logger.error(
+      "The signer ({keyId}) and the actor ({actorId}) do not match.",
+      { activity: json, keyId: key.id?.href, actorId: activity.actorId.href },
+    );
     const response = new Response("The signer and the actor do not match.", {
       status: 401,
       headers: { "Content-Type": "text/plain; charset=utf-8" },
@@ -303,6 +322,10 @@ export async function handleInbox<TContextData>(
   while (true) {
     if (inboxListeners.has(cls)) break;
     if (cls === Activity) {
+      logger.error(
+        "Unsupported activity type:\n{activity}",
+        { activity: json },
+      );
       return new Response("", {
         status: 202,
         headers: { "Content-Type": "text/plain; charset=utf-8" },
@@ -313,8 +336,12 @@ export async function handleInbox<TContextData>(
   const listener = inboxListeners.get(cls)!;
   try {
     await listener(context, activity);
-  } catch (e) {
-    await inboxErrorHandler?.(context, e);
+  } catch (error) {
+    logger.error(
+      "Failed to process the activity:\n{error}",
+      { error, activity: json },
+    );
+    await inboxErrorHandler?.(context, error);
     return new Response("Internal server error.", {
       status: 500,
       headers: { "Content-Type": "text/plain; charset=utf-8" },
@@ -323,6 +350,10 @@ export async function handleInbox<TContextData>(
   if (cacheKey != null) {
     await kv.set(cacheKey, true, { ttl: Temporal.Duration.from({ days: 1 }) });
   }
+  logger.info(
+    "Activity {activityId} has been processed.",
+    { activityId: activity.id?.href, activity: json },
+  );
   return new Response("", {
     status: 202,
     headers: { "Content-Type": "text/plain; charset=utf-8" },

federation/middleware.ts

@@ -1,4 +1,5 @@
 import { Temporal } from "@js-temporal/polyfill";
+import { getLogger } from "@logtape/logtape";
 import { exportJwk, importJwk, validateCryptoKey } from "../httpsig/key.ts";
 import { getKeyOwner, verify } from "../httpsig/mod.ts";
 import { handleNodeInfo, handleNodeInfoJrd } from "../nodeinfo/handler.ts";
@@ -199,6 +200,8 @@ export class Federation<TContextData> {
 
   #startQueue() {
     if (this.#queue != null && !this.#queueStarted) {
+      getLogger(["fedify", "federation", "outbox"])
+        .debug("Starting an outbox queue.");
       this.#queue?.listen(this.#listenQueue.bind(this));
       this.#queueStarted = true;
     }
@@ -745,7 +748,12 @@ export class Federation<TContextData> {
     activity: Activity,
     { preferSharedInbox, immediate }: SendActivityOptions = {},
   ): Promise<void> {
+    const logger = getLogger(["fedify", "federation", "outbox"]);
     if (activity.actorId == null) {
+      logger.error(
+        "Activity {activityId} to send does not have an actor.",
+        { activity, activityId: activity?.id?.href },
+      );
       throw new TypeError(
         "The activity to send must have at least one actor property.",
       );
@@ -761,7 +769,23 @@ export class Federation<TContextData> {
       recipients: Array.isArray(recipients) ? recipients : [recipients],
       preferSharedInbox,
     });
+    logger.debug(
+      "Sending activity {activityId} to inboxes:\n{inboxes}",
+      { inboxes, activityId: activity.id?.href, activity },
+    );
     if (immediate || this.#queue == null) {
+      if (immediate) {
+        logger.debug(
+          "Sending activity immediately without queue since immediate option " +
+            "is set.",
+          { activityId: activity.id?.href, activity },
+        );
+      } else {
+        logger.debug(
+          "Sending activity immediately without queue since queue is not set.",
+          { activityId: activity.id?.href, activity },
+        );
+      }
       const documentLoader = this.#authenticatedDocumentLoaderFactory(
         { keyId, privateKey },
       );
@@ -780,6 +804,10 @@ export class Federation<TContextData> {
       await Promise.all(promises);
       return;
     }
+    logger.debug(
+      "Enqueuing activity {activityId} to send later.",
+      { activityId: activity.id?.href, activity },
+    );
     const privateKeyJwk = await exportJwk(privateKey);
     const activityJson = await activity.toJsonLd({ expand: true });
     for (const inbox of inboxes) {
@@ -835,7 +863,6 @@ export class Federation<TContextData> {
       contextData,
     }: FederationFetchOptions<TContextData>,
   ): Promise<Response> {
-    this.#startQueue();
     onNotFound ??= notFound;
     onNotAcceptable ??= notAcceptable;
     onUnauthorized ??= unauthorized;