diff --git a/.github/workflows/build.yaml b/.github/workflows/build.yaml index 9cabed9e..3d4ee983 100644 --- a/.github/workflows/build.yaml +++ b/.github/workflows/build.yaml @@ -19,6 +19,8 @@ jobs: with: deno-version: v1.x - run: deno task test --coverage=.cov --junit-path=.test-report.xml + env: + RUST_BACKTRACE: "1" - uses: EnricoMi/publish-unit-test-result-action@v2 if: runner.os == 'Linux' && always() with: diff --git a/.gitignore b/.gitignore index de68b345..61683a29 100644 --- a/.gitignore +++ b/.gitignore @@ -1,5 +1,6 @@ .cov/ .cov.lcov +.dnt-import-map.json .DS_Store .test-report.xml apidoc/ diff --git a/.vscode/settings.json b/.vscode/settings.json index eca2156c..bf4b4f1b 100755 --- a/.vscode/settings.json +++ b/.vscode/settings.json @@ -54,6 +54,7 @@ "keypair", "langstr", "Lemmy", + "logtape", "lume", "lumocs", "metas", diff --git a/deno.json b/deno.json index c5e03005..645b9586 100644 --- a/deno.json +++ b/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", diff --git a/dnt.ts b/dnt.ts index 75ecc437..2f033ded 100644 --- a/dnt.ts +++ b/dnt.ts @@ -20,6 +20,18 @@ for (const { name } of entryPoints) { if (match && match[1] != "x") testExports.push(match[1]); } +const importMap = ".dnt-import-map.json"; +await Deno.writeTextFile( + importMap, + JSON.stringify({ + imports: { + ...metadata.imports, + "@logtape/logtape": metadata.imports["@logtape/logtape"] + .replace(/^jsr:/, "npm:"), + }, + }), +); + await build({ package: { // package.json properties @@ -44,7 +56,7 @@ await build({ }, outDir: "./npm", entryPoints, - importMap: denoJson, + importMap, scriptModule: false, shims: { deno: true, @@ -105,4 +117,6 @@ await build({ }, }); +await Deno.remove(importMap); + // cSpell: ignore Minhee 2KNRVU diff --git a/docs/.vitepress/config.mts b/docs/.vitepress/config.mts index eaaf3b53..de016eba 100644 --- a/docs/.vitepress/config.mts +++ b/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" }, ], }, { diff --git a/docs/manual.md b/docs/manual.md index 73e2f90a..0212248f 100644 --- a/docs/manual.md +++ b/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, diff --git a/docs/manual/log.md b/docs/manual/log.md new file mode 100644 index 00000000..c5c37e46 --- /dev/null +++ b/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 diff --git a/docs/manual/test.md b/docs/manual/test.md index 22cacbce..868e3f22 100644 --- a/docs/manual/test.md +++ b/docs/manual/test.md @@ -6,7 +6,9 @@ description: >- prev: text: Integration link: ./integration.md -next: false +next: + text: Logging + link: ./log.md --- Testing diff --git a/federation/handler.ts b/federation/handler.ts index f6a391c3..0e1dfdda 100644 --- a/federation/handler.ts +++ b/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( onNotFound, }: InboxHandlerParameters, ): Promise { - 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( 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( 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( 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,6 +297,7 @@ export async function handleInbox( } } 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" }, @@ -290,6 +305,10 @@ export async function handleInbox( 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( 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( 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( 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" }, diff --git a/federation/middleware.ts b/federation/middleware.ts index 66d67c2e..96307750 100644 --- a/federation/middleware.ts +++ b/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 { #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 { activity: Activity, { preferSharedInbox, immediate }: SendActivityOptions = {}, ): Promise { + 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 { 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 { 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 { contextData, }: FederationFetchOptions, ): Promise { - this.#startQueue(); onNotFound ??= notFound; onNotAcceptable ??= notAcceptable; onUnauthorized ??= unauthorized; diff --git a/federation/send.test.ts b/federation/send.test.ts index 5e2e191c..8fb1a975 100644 --- a/federation/send.test.ts +++ b/federation/send.test.ts @@ -1,3 +1,4 @@ +import { configure, getConsoleSink, reset } from "@logtape/logtape"; import { assertEquals, assertNotEquals, @@ -72,6 +73,25 @@ Deno.test("extractInboxes()", () => { Deno.test("sendActivity()", async (t) => { mf.install(); + await configure({ + sinks: { + console: getConsoleSink(), + }, + filters: {}, + loggers: [ + { + category: ["fedify", "federation", "outbox"], + level: "debug", + sinks: ["console"], + }, + { + category: ["logtape", "meta"], + level: "warning", + sinks: ["console"], + }, + ], + }); + let verified: boolean | null = null; let request: Request | null = null; mf.mock("POST@/inbox", async (req) => { @@ -120,6 +140,7 @@ Deno.test("sendActivity()", async (t) => { await t.step("failure", async () => { let activity = new Create({ + id: new URL("https://example.com/activity"), actor: new URL("https://example.com/person"), }); await assertRejects( @@ -132,8 +153,8 @@ Deno.test("sendActivity()", async (t) => { documentLoader: mockDocumentLoader, }), Error, - "Failed to send activity to https://example.com/inbox2 " + - "(500 Internal Server Error):\n" + + "Failed to send activity https://example.com/activity to " + + "https://example.com/inbox2 (500 Internal Server Error):\n" + "something went wrong", ); @@ -152,5 +173,6 @@ Deno.test("sendActivity()", async (t) => { ); }); + await reset(); mf.uninstall(); }); diff --git a/federation/send.ts b/federation/send.ts index cff1a271..fbd8a0b3 100644 --- a/federation/send.ts +++ b/federation/send.ts @@ -1,3 +1,4 @@ +import { getLogger } from "@logtape/logtape"; import { sign } from "../httpsig/mod.ts"; import type { DocumentLoader } from "../runtime/docloader.ts"; import type { Actor } from "../vocab/actor.ts"; @@ -84,6 +85,7 @@ export async function sendActivity( documentLoader, }: SendActivityParameters, ): Promise { + const logger = getLogger(["fedify", "federation", "outbox"]); if (activity.actorId == null) { throw new TypeError( "The activity to send must have at least one actor property.", @@ -100,10 +102,21 @@ export async function sendActivity( request = await sign(request, privateKey, keyId); const response = await fetch(request); if (!response.ok) { + const error = await response.text(); + logger.error( + "Failed to send activity {activityId} to {inbox} ({status} " + + "{statusText}):\n{error}", + { + activityId: activity.id?.href, + inbox: inbox.href, + status: response.status, + statusText: response.statusText, + error, + }, + ); throw new Error( - `Failed to send activity to ${inbox} ` + - `(${response.status} ${response.statusText}):\n` + - await response.text(), + `Failed to send activity ${activity?.id?.href} to ${inbox.href} ` + + `(${response.status} ${response.statusText}):\n${error}`, ); } }