More logs

deno.json

@@ -29,7 +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",
+    "@logtape/logtape": "jsr:@logtape/logtape@^0.2.2",
     "@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",

examples/blog/.vscode/settings.json

@@ -39,6 +39,7 @@
     "fediverse",
     "halfyear",
     "httpsig",
+    "logtape",
     "nodeinfo",
     "preact",
     "unfollow",

examples/blog/federation/mod.ts

@@ -5,6 +5,7 @@ import { Federation } from "@fedify/fedify/federation";
 import {
   Accept,
   Activity,
+  Article,
   Create,
   Endpoints,
   Follow,
@@ -26,6 +27,9 @@ import {
 } from "../models/follower.ts";
 import { countPosts, getPosts, toArticle } from "../models/post.ts";
 import { openKv } from "../models/kv.ts";
+import { getLogger } from "@logtape/logtape";
+
+const logger = getLogger(["blog", "federation"]);
 
 // The `Federation<TContextData>` object is a registry that registers
 // federation-related callbacks:
@@ -177,7 +181,7 @@ federation.setInboxListeners("/users/{handle}/inbox", "/inbox")
   // The `Create` activity is handled by adding a comment to the post:
   .on(Create, async (ctx, create) => {
     const object = await create.getObject(ctx);
-    if (object instanceof Note) {
+    if (object instanceof Note || object instanceof Article) {
       if (object.id == null || object.content == null) return;
       const author = await object.getAttribution();
       if (
@@ -205,7 +209,10 @@ federation.setInboxListeners("/users/{handle}/inbox", "/inbox")
         await addComment({ ...comment, postUuid });
       }
     } else {
-      console.debug(object);
+      logger.getChild("inbox").warn(
+        "Unsupported object type ({type}) for Create activity: {object}",
+        { type: object?.constructor.name, object },
+      );
     }
   })
   // The `Undo` activity purposes to undo the previous activity.  In this
@@ -217,10 +224,19 @@ federation.setInboxListeners("/users/{handle}/inbox", "/inbox")
       if (activity.id == null) return;
       await removeFollower(activity.id.href);
     } else {
-      console.debug(undo);
+      logger.getChild("inbox").warn(
+        "Unsupported object type ({type}) for Undo activity: {object}",
+        { type: activity?.constructor.name, object: activity },
+      );
     }
   })
-  .onError((_ctx, e) => console.error(e));
+  .onError((_ctx, error) => {
+    logger.getChild("inbox").error(
+      "An error occurred while processing an activity in the inbox handler:\n" +
+        "{error}",
+      { error },
+    );
+  });
 
 // Since the blog does not follow anyone, the following dispatcher is
 // implemented to return just an empty list:

examples/blog/fresh.config.ts

@@ -1,3 +1,4 @@
 import { defineConfig } from "$fresh/server.ts";
+import "./loggers.ts";
 
 export default defineConfig({});

examples/blog/import_map.g.json

@@ -15,7 +15,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",
+    "@logtape/logtape": "jsr:@logtape/logtape@^0.2.2",
     "@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",

examples/blog/loggers.ts

@@ -0,0 +1,23 @@
+import { configure, getConsoleSink, type LogLevel } from "@logtape/logtape";
+
+await configure({
+  sinks: { console: getConsoleSink() },
+  filters: {},
+  loggers: [
+    {
+      category: "fedify",
+      level: (Deno.env.get("FEDIFY_LOG") as LogLevel | undefined) ?? "debug",
+      sinks: ["console"],
+    },
+    {
+      category: "blog",
+      level: (Deno.env.get("BLOG_LOG") as LogLevel | undefined) ?? "debug",
+      sinks: ["console"],
+    },
+    {
+      category: ["logtape", "meta"],
+      level: "warning",
+      sinks: ["console"],
+    },
+  ],
+});

examples/blog/models/post.ts

@@ -6,6 +6,9 @@ import { uuidv7 } from "uuidv7";
 import { Blog } from "./blog.ts";
 import { Comment } from "./comment.ts";
 import { openKv } from "./kv.ts";
+import { getLogger } from "@logtape/logtape";
+
+const logger = getLogger(["blog", "models", "post"]);
 
 export interface Post {
   uuid: string;
@@ -27,6 +30,7 @@ export async function addPost(post: Omit<Post, "uuid"> | Post): Promise<Post> {
     .set(["post", uuid], newPost)
     .sum(["count"], 1n)
     .commit();
+  logger.debug("Added post {uuid}.", { uuid, post: newPost });
   return { uuid, ...post };
 }
 

examples/blog/routes/posts/index.tsx

@@ -82,7 +82,7 @@ export const handler: Handlers<PostsData> = {
       published: Temporal.Now.instant(),
     });
     // Gets a federation context for enqueueing an activity:
-    const fedCtx = await federation.createContext(req);
+    const fedCtx = federation.createContext(req);
     // Enqueues a `Create` activity to the outbox:
     await fedCtx.sendActivity(
       { handle: blog.handle },

federation/middleware.ts

@@ -200,14 +200,15 @@ export class Federation<TContextData> {
 
   #startQueue() {
     if (this.#queue != null && !this.#queueStarted) {
-      getLogger(["fedify", "federation", "outbox"])
-        .debug("Starting an outbox queue.");
+      const logger = getLogger(["fedify", "federation", "outbox"]);
+      logger.debug("Starting an outbox queue.");
       this.#queue?.listen(this.#listenQueue.bind(this));
       this.#queueStarted = true;
     }
   }
 
   async #listenQueue(message: OutboxMessage): Promise<void> {
+    const logger = getLogger(["fedify", "federation", "outbox"]);
     let activity: Activity | null = null;
     try {
       const keyId = new URL(message.keyId);
@@ -225,19 +226,38 @@ export class Federation<TContextData> {
         inbox: new URL(message.inbox),
         documentLoader,
       });
-    } catch (e) {
+    } catch (error) {
       try {
-        this.#onOutboxError?.(e, activity);
-      } catch (_) {
-        // Ignore errors in the error handler.
+        this.#onOutboxError?.(error, activity);
+      } catch (error) {
+        logger.error(
+          "An unexpected error occurred in onError handler:\n{error}",
+          { ...message, error, activityId: activity?.id?.href },
+        );
       }
       if (message.trial < this.#backoffSchedule.length) {
+        logger.error(
+          "Failed to send activity {activityId} to {inbox} (trial #{trial})" +
+            "; retry...:\n{error}",
+          { ...message, error, activityId: activity?.id?.href },
+        );
         this.#queue?.enqueue({
           ...message,
           trial: message.trial + 1,
         }, { delay: this.#backoffSchedule[message.trial] });
+      } else {
+        logger.error(
+          "Failed to send activity {activityId} to {inbox} after {trial} " +
+            "trials; giving up:\n{error}",
+          { ...message, error, activityId: activity?.id?.href },
+        );
       }
+      return;
     }
+    logger.info(
+      "Successfully sent activity {activityId} to {inbox}.",
+      { ...message, activityId: activity?.id?.href },
+    );
   }
 
   /**
@@ -769,10 +789,11 @@ 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 },
-    );
+    logger.debug("Sending activity {activityId} to inboxes:\n{inboxes}", {
+      inboxes: [...inboxes].map((u) => u.href),
+      activityId: activity.id?.href,
+      activity,
+    });
     if (immediate || this.#queue == null) {
       if (immediate) {
         logger.debug(