diff --git a/CHANGES.md b/CHANGES.md index 1e1cbdb97..664494ca8 100644 --- a/CHANGES.md +++ b/CHANGES.md @@ -41,6 +41,21 @@ To be released. attributes, and `TraceActivityRecord.activityJson` is present only when the span event includes full activity JSON. [[#316], [#619], [#755]] + - Added two OpenTelemetry histograms for signature verification: + `activitypub.signature.verification.duration` measures end-to-end + verification time for HTTP Signatures, Linked Data Signatures, and + Object Integrity Proofs (including local key lookup and remote key + fetches), and `activitypub.signature.key_fetch.duration` measures + public key lookup duration separately so operators can isolate + non-fetch verification work. Both instruments carry + `activitypub.signature.kind` (`http`, `linked_data`, or + `object_integrity`) and bounded result attributes; the verification + histogram additionally carries spec-bounded + `http_signatures.algorithm`, `ld_signatures.type`, or + `object_integrity_proofs.cryptosuite` when known, plus + `http_signatures.failure_reason` on rejected HTTP rows. + [[#316], [#737], [#769]] + - Added OpenTelemetry HTTP server metrics for inbound requests handled by `Federation.fetch()`: `fedify.http.server.request.count` (Counter) and `fedify.http.server.request.duration` (Histogram). Both instruments carry @@ -80,6 +95,7 @@ To be released. [#619]: https://github.com/fedify-dev/fedify/issues/619 [#735]: https://github.com/fedify-dev/fedify/issues/735 [#736]: https://github.com/fedify-dev/fedify/issues/736 +[#737]: https://github.com/fedify-dev/fedify/issues/737 [#740]: https://github.com/fedify-dev/fedify/issues/740 [#748]: https://github.com/fedify-dev/fedify/pull/748 [#752]: https://github.com/fedify-dev/fedify/issues/752 @@ -87,6 +103,7 @@ To be released. [#755]: https://github.com/fedify-dev/fedify/pull/755 [#757]: https://github.com/fedify-dev/fedify/pull/757 [#759]: https://github.com/fedify-dev/fedify/pull/759 +[#769]: https://github.com/fedify-dev/fedify/pull/769 ### @fedify/fixture diff --git a/docs/manual/opentelemetry.md b/docs/manual/opentelemetry.md index 3eb5acc64..404293aa1 100644 --- a/docs/manual/opentelemetry.md +++ b/docs/manual/opentelemetry.md @@ -296,21 +296,23 @@ Instrumented metrics Fedify records the following OpenTelemetry metrics: -| Metric name | Instrument | Unit | Description | -| -------------------------------------------- | ------------- | ----------- | --------------------------------------------------------------- | -| `activitypub.delivery.sent` | Counter | `{attempt}` | Counts outgoing ActivityPub delivery attempts. | -| `activitypub.delivery.permanent_failure` | Counter | `{failure}` | Counts outgoing deliveries abandoned as permanent failures. | -| `activitypub.delivery.duration` | Histogram | `ms` | Measures outgoing ActivityPub delivery attempt duration. | -| `activitypub.inbox.processing_duration` | Histogram | `ms` | Measures inbox listener processing duration. | -| `activitypub.signature.verification_failure` | Counter | `{failure}` | Counts failed signature verification for inbox requests. | -| `fedify.http.server.request.count` | Counter | `{request}` | Counts inbound HTTP requests handled by `Federation.fetch()`. | -| `fedify.http.server.request.duration` | Histogram | `ms` | Measures inbound HTTP request duration in `Federation.fetch()`. | -| `fedify.queue.task.enqueued` | Counter | `{task}` | Counts inbox, outbox, and fanout tasks Fedify enqueued. | -| `fedify.queue.task.started` | Counter | `{task}` | Counts queue tasks Fedify began processing as a worker. | -| `fedify.queue.task.completed` | Counter | `{task}` | Counts queue tasks Fedify finished processing without throwing. | -| `fedify.queue.task.failed` | Counter | `{task}` | Counts queue tasks Fedify abandoned because processing threw. | -| `fedify.queue.task.duration` | Histogram | `ms` | Measures queue task processing duration in Fedify workers. | -| `fedify.queue.task.in_flight` | UpDownCounter | `{task}` | Tracks queue tasks currently in flight in this Fedify process. | +| Metric name | Instrument | Unit | Description | +| --------------------------------------------- | ------------- | ----------- | ----------------------------------------------------------------------------------------------- | +| `activitypub.delivery.sent` | Counter | `{attempt}` | Counts outgoing ActivityPub delivery attempts. | +| `activitypub.delivery.permanent_failure` | Counter | `{failure}` | Counts outgoing deliveries abandoned as permanent failures. | +| `activitypub.delivery.duration` | Histogram | `ms` | Measures outgoing ActivityPub delivery attempt duration. | +| `activitypub.inbox.processing_duration` | Histogram | `ms` | Measures inbox listener processing duration. | +| `activitypub.signature.verification_failure` | Counter | `{failure}` | Counts failed signature verification for inbox requests. | +| `activitypub.signature.verification.duration` | Histogram | `ms` | Measures signature verification duration across HTTP, Linked Data, and Object Integrity Proofs. | +| `activitypub.signature.key_fetch.duration` | Histogram | `ms` | Measures public key lookup duration during signature verification. | +| `fedify.http.server.request.count` | Counter | `{request}` | Counts inbound HTTP requests handled by `Federation.fetch()`. | +| `fedify.http.server.request.duration` | Histogram | `ms` | Measures inbound HTTP request duration in `Federation.fetch()`. | +| `fedify.queue.task.enqueued` | Counter | `{task}` | Counts inbox, outbox, and fanout tasks Fedify enqueued. | +| `fedify.queue.task.started` | Counter | `{task}` | Counts queue tasks Fedify began processing as a worker. | +| `fedify.queue.task.completed` | Counter | `{task}` | Counts queue tasks Fedify finished processing without throwing. | +| `fedify.queue.task.failed` | Counter | `{task}` | Counts queue tasks Fedify abandoned because processing threw. | +| `fedify.queue.task.duration` | Histogram | `ms` | Measures queue task processing duration in Fedify workers. | +| `fedify.queue.task.in_flight` | UpDownCounter | `{task}` | Tracks queue tasks currently in flight in this Fedify process. | ### Metric attributes @@ -332,6 +334,81 @@ Fedify records the following OpenTelemetry metrics: : `activitypub.verification.failure_reason`, plus `activitypub.remote.host` when the failed signature includes a key ID. +`activitypub.signature.verification.duration` +: `activitypub.signature.kind` is always present and is one of `http`, + `linked_data`, or `object_integrity`. `activitypub.signature.result` is + always present and is one of: + + - `verified`: the signature was checked and accepted. + - `rejected`: the signature was checked and refused (bad signature, + key fetch failure, owner mismatch, etc.). + - `missing`: no signature was present. Only `http` and `linked_data` + produce this value; `object_integrity` does not, because the caller + decides whether to invoke proof verification at all. + - `error`: verification threw an unexpected error. + + The duration covers the full verification path Fedify performs, + *including* local key lookup and remote key fetches; the separate + `activitypub.signature.key_fetch.duration` histogram lets operators + subtract key lookup latency from the total to isolate the rest of the + verification work (canonicalization, hashing, attribution and owner + checks, cryptographic verification, etc.). Direct calls to + `verifyRequest()` / `verifyRequestDetailed()`, `verifyJsonLd()`, and + `verifyProof()` each emit exactly one measurement, even when the + implementation retries internally after a cache mismatch. Wrappers + such as `verifyObject()` emit one measurement per inner `verifyProof()` + call (and none when the object has no proofs); higher-level inbox + handling can perform several verification attempts in series. + + Kind-specific optional attributes are recorded only when the value + matches a small, spec-bounded set, to keep cardinality safe even when + attacker-supplied JSON-LD or signature headers reach the verifier: + + - `http_signatures.algorithm` (HTTP only) is recorded only when the + parsed algorithm value is one of `rsa-sha1`, `rsa-sha256`, + `rsa-sha512`, `ecdsa-sha256`, `ecdsa-sha384`, `ecdsa-sha512`, + `ed25519`, or `hs2019` (draft-cavage) or one of the keys of the + RFC 9421 algorithm map (`rsa-v1_5-sha256`, `rsa-v1_5-sha512`, + `rsa-pss-sha512`, `ecdsa-p256-sha256`, `ecdsa-p384-sha384`, + `ed25519`). + - `http_signatures.failure_reason` (HTTP only, on `rejected` rows) + is one of `invalidSignature` or `keyFetchError`. HTTP requests + with no signature header are reported as + `activitypub.signature.result=missing` and do not carry a + `http_signatures.failure_reason`. + - `ld_signatures.type` (Linked Data only) is recorded only for the + spec-supported `RsaSignature2017` type. + - `object_integrity_proofs.cryptosuite` (Object Integrity Proofs + only) is recorded only for the spec-supported `eddsa-jcs-2022` + cryptosuite. + + Key IDs, actor IDs, request URLs, and object IDs are deliberately + excluded from this histogram. They remain on the corresponding spans + (`http_signatures.verify`, `ld_signatures.verify`, + `object_integrity_proofs.verify`) for trace-level investigation. + +`activitypub.signature.key_fetch.duration` +: `activitypub.signature.kind` is always present (same values as above). + `activitypub.signature.key_fetch.result` is always present and is one + of: + + - `hit`: the public key was served by the configured `KeyCache` + (which may itself be backed by a remote store such as Redis or a + database; the measurement reflects whatever round trip that + backend incurs). + - `fetched`: the key was not in the cache and was loaded through + the document loader, returning a usable key. This typically + corresponds to a network fetch, but a custom document loader + that serves from a local store will also fall in this bucket. + - `error`: no usable key came back (HTTP failure, invalid response + body, cached negative entry, thrown exception, etc.). + + Unlike `activitypub.signature.verification.duration`, this histogram + is recorded *per fetch attempt*: a verification that retries after a + cache mismatch emits two key fetch measurements (typically one `hit` + for the stale attempt and one `fetched` for the freshly fetched retry) + alongside the single verification measurement that covers both. + `fedify.http.server.request.count` and `fedify.http.server.request.duration` : `http.request.method` and `fedify.endpoint` are always present. `http.request.method` is normalized to one of the standard HTTP methods diff --git a/packages/fedify/src/federation/handler.ts b/packages/fedify/src/federation/handler.ts index 5f6dc0ed9..ddca7e8cb 100644 --- a/packages/fedify/src/federation/handler.ts +++ b/packages/fedify/src/federation/handler.ts @@ -842,6 +842,7 @@ async function handleInboxInternal( signatureTimeWindow, skipSignatureVerification, inboxChallengePolicy, + meterProvider, tracerProvider, } = parameters; const logger = getLogger(["fedify", "federation", "inbox"]); @@ -913,6 +914,7 @@ async function handleInboxInternal( contextLoader: ctx.contextLoader, documentLoader: ctx.documentLoader, keyCache, + meterProvider, tracerProvider, }); } catch (error) { @@ -942,6 +944,7 @@ async function handleInboxInternal( contextLoader: ctx.contextLoader, documentLoader: ctx.documentLoader, keyCache, + meterProvider, tracerProvider, }); } catch (error) { @@ -991,6 +994,7 @@ async function handleInboxInternal( documentLoader: ctx.documentLoader, timeWindow: signatureTimeWindow, keyCache, + meterProvider, tracerProvider, }); if (verification.verified === false) { diff --git a/packages/fedify/src/federation/metrics.ts b/packages/fedify/src/federation/metrics.ts index 34169bcf2..293d8322b 100644 --- a/packages/fedify/src/federation/metrics.ts +++ b/packages/fedify/src/federation/metrics.ts @@ -31,10 +31,85 @@ export interface QueueTaskCommonAttributes { activityType?: string; } +/** + * The kind of ActivityPub signature verified, used as the + * `activitypub.signature.kind` metric attribute. + * @since 2.3.0 + */ +export type SignatureVerificationKind = + | "http" + | "linked_data" + | "object_integrity"; + +/** + * The terminal classification of a signature verification attempt, used as + * the `activitypub.signature.result` metric attribute. + * + * - `verified`: the signature was checked and accepted. + * - `rejected`: the signature was checked and refused (bad signature, key + * fetch failure, owner mismatch, etc.). + * - `missing`: no signature was present. Only HTTP Signatures and Linked + * Data Signatures distinguish this from `rejected`; Object Integrity + * Proofs never carry this value because callers decide whether to invoke + * {@link import("../sig/proof.ts").verifyProof} at all. + * - `error`: verification threw an unexpected error. + * @since 2.3.0 + */ +export type SignatureVerificationResult = + | "verified" + | "rejected" + | "missing" + | "error"; + +/** + * The terminal classification of a public key fetch performed as part of + * signature verification, used as the + * `activitypub.signature.key_fetch.result` metric attribute. + * + * - `hit`: the public key was served by the configured `KeyCache`. The + * `KeyCache` itself may be backed by a remote store such as Redis or a + * database, in which case the measurement reflects whatever round trip + * that backend incurs. + * - `fetched`: the public key was not in the cache and was loaded + * through the document loader, returning a usable key. This typically + * corresponds to a network fetch, but a custom document loader that + * serves from a local store will also fall in this bucket. + * - `error`: the fetch attempt returned no usable key (HTTP failure, + * invalid response body, cached negative entry, thrown exception, + * etc.). + * @since 2.3.0 + */ +export type SignatureKeyFetchResult = "hit" | "fetched" | "error"; + +/** + * Optional attributes recorded alongside an + * `activitypub.signature.verification.duration` measurement. Each field is + * scoped to the matching signature kind and is omitted when its value is not + * available; values are expected to come from small, spec-bounded sets so + * they do not inflate metric cardinality. + * @since 2.3.0 + */ +export interface SignatureVerificationExtraAttributes { + /** `http_signatures.algorithm` (HTTP Signatures only). */ + algorithm?: string; + /** `ld_signatures.type` (Linked Data Signatures only). */ + ldType?: string; + /** `object_integrity_proofs.cryptosuite` (Object Integrity Proofs only). */ + cryptosuite?: string; + /** + * `http_signatures.failure_reason`, recorded only on HTTP Signature + * failures so the histogram can be sliced by reason without exploding + * cardinality on success rows. + */ + failureReason?: string; +} + class FederationMetrics { readonly deliverySent: Counter; readonly deliveryPermanentFailure: Counter; readonly signatureVerificationFailure: Counter; + readonly signatureVerificationDuration: Histogram; + readonly signatureKeyFetchDuration: Histogram; readonly deliveryDuration: Histogram; readonly inboxProcessingDuration: Histogram; readonly httpServerRequestCount: Counter; @@ -66,6 +141,24 @@ class FederationMetrics { unit: "{failure}", }, ); + this.signatureVerificationDuration = meter.createHistogram( + "activitypub.signature.verification.duration", + { + description: + "Duration of ActivityPub signature verification, including local " + + "key lookup and remote key fetches.", + unit: "ms", + }, + ); + this.signatureKeyFetchDuration = meter.createHistogram( + "activitypub.signature.key_fetch.duration", + { + description: + "Duration of public key lookup performed during ActivityPub " + + "signature verification.", + unit: "ms", + }, + ); this.deliveryDuration = meter.createHistogram( "activitypub.delivery.duration", { @@ -208,6 +301,42 @@ class FederationMetrics { this.signatureVerificationFailure.add(1, attributes); } + recordSignatureVerificationDuration( + durationMs: number, + kind: SignatureVerificationKind, + result: SignatureVerificationResult, + extra: SignatureVerificationExtraAttributes = {}, + ): void { + const attributes: Attributes = { + "activitypub.signature.kind": kind, + "activitypub.signature.result": result, + }; + if (extra.algorithm != null) { + attributes["http_signatures.algorithm"] = extra.algorithm; + } + if (extra.failureReason != null) { + attributes["http_signatures.failure_reason"] = extra.failureReason; + } + if (extra.ldType != null) { + attributes["ld_signatures.type"] = extra.ldType; + } + if (extra.cryptosuite != null) { + attributes["object_integrity_proofs.cryptosuite"] = extra.cryptosuite; + } + this.signatureVerificationDuration.record(durationMs, attributes); + } + + recordSignatureKeyFetchDuration( + durationMs: number, + kind: SignatureVerificationKind, + result: SignatureKeyFetchResult, + ): void { + this.signatureKeyFetchDuration.record(durationMs, { + "activitypub.signature.kind": kind, + "activitypub.signature.key_fetch.result": result, + }); + } + recordInboxProcessingDuration( activityType: string, durationMs: number, diff --git a/packages/fedify/src/federation/middleware.ts b/packages/fedify/src/federation/middleware.ts index b75237bb8..f52e00318 100644 --- a/packages/fedify/src/federation/middleware.ts +++ b/packages/fedify/src/federation/middleware.ts @@ -2862,6 +2862,7 @@ export class ContextImpl implements Context { { contextLoader, documentLoader: options.documentLoader ?? this.documentLoader, + meterProvider: this.meterProvider, tracerProvider: options.tracerProvider ?? this.tracerProvider, keyCache, }, @@ -3089,6 +3090,7 @@ class RequestContextImpl extends ContextImpl contextLoader: options.contextLoader ?? this.contextLoader, documentLoader: options.documentLoader ?? this.documentLoader, timeWindow: this.federation.signatureTimeWindow, + meterProvider: this.meterProvider, tracerProvider: options.tracerProvider ?? this.tracerProvider, }); } diff --git a/packages/fedify/src/sig/http.test.ts b/packages/fedify/src/sig/http.test.ts index 1f61dfd2b..b05417e7c 100644 --- a/packages/fedify/src/sig/http.test.ts +++ b/packages/fedify/src/sig/http.test.ts @@ -1,4 +1,5 @@ import { + createTestMeterProvider, createTestTracerProvider, mockDocumentLoader, test, @@ -10,6 +11,7 @@ import { assertEquals, assertExists, assertFalse, + assertGreaterOrEqual, assertRejects, assertStringIncludes, assertThrows, @@ -367,6 +369,394 @@ test("verifyRequestDetailed() records failure details on span", async () => { assertEquals(span.attributes["http_signatures.key_fetch_status"], 410); }); +test("verifyRequestDetailed() records verification duration metric", async (t) => { + const buildSignedRequest = (): Promise => + signRequest( + new Request("https://example.com/inbox", { + method: "POST", + headers: { + "Content-Type": "application/activity+json", + accept: "application/ld+json", + }, + body: JSON.stringify({ + "@context": "https://www.w3.org/ns/activitystreams", + type: "Create", + actor: "https://example.com/key2", + }), + }), + rsaPrivateKey2, + new URL("https://example.com/key2"), + ); + + await t.step("verified path emits one measurement", async () => { + const [meterProvider, recorder] = createTestMeterProvider(); + const request = await buildSignedRequest(); + + const result = await verifyRequestDetailed(request, { + contextLoader: mockDocumentLoader, + documentLoader: mockDocumentLoader, + meterProvider, + }); + assert(result.verified); + + const measurements = recorder.getMeasurements( + "activitypub.signature.verification.duration", + ); + assertEquals(measurements.length, 1); + const measurement = measurements[0]; + assertEquals(measurement.type, "histogram"); + assertGreaterOrEqual(measurement.value, 0); + assertEquals( + measurement.attributes["activitypub.signature.kind"], + "http", + ); + assertEquals( + measurement.attributes["activitypub.signature.result"], + "verified", + ); + assertEquals( + measurement.attributes["http_signatures.algorithm"], + "rsa-sha256", + ); + assertFalse( + "http_signatures.failure_reason" in measurement.attributes, + ); + }); + + await t.step("missing signature is recorded as result=missing", async () => { + const [meterProvider, recorder] = createTestMeterProvider(); + const result = await verifyRequestDetailed( + new Request("https://example.com/inbox", { + method: "POST", + headers: { "Content-Type": "application/activity+json" }, + body: "{}", + }), + { + contextLoader: mockDocumentLoader, + documentLoader: mockDocumentLoader, + meterProvider, + }, + ); + assertFalse(result.verified); + assertEquals(result.reason.type, "noSignature"); + + const measurements = recorder.getMeasurements( + "activitypub.signature.verification.duration", + ); + assertEquals(measurements.length, 1); + assertEquals( + measurements[0].attributes["activitypub.signature.kind"], + "http", + ); + assertEquals( + measurements[0].attributes["activitypub.signature.result"], + "missing", + ); + assertFalse( + "http_signatures.failure_reason" in measurements[0].attributes, + ); + }); + + await t.step( + "invalid signature is recorded as result=rejected with failure_reason", + async () => { + const [meterProvider, recorder] = createTestMeterProvider(); + const result = await verifyRequestDetailed( + new Request("https://example.com/", { + method: "POST", + headers: { + Date: "Tue, 05 Mar 2024 07:49:44 GMT", + Digest: "sha-256=47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=", + Signature: 'keyId="https://example.com/key2",' + + 'headers="(request-target) date digest",signature="AAAA"', + }, + body: "", + }), + { + documentLoader: mockDocumentLoader, + contextLoader: mockDocumentLoader, + meterProvider, + }, + ); + assertFalse(result.verified); + assertEquals(result.reason.type, "invalidSignature"); + + const measurements = recorder.getMeasurements( + "activitypub.signature.verification.duration", + ); + assertEquals(measurements.length, 1); + assertEquals( + measurements[0].attributes["activitypub.signature.kind"], + "http", + ); + assertEquals( + measurements[0].attributes["activitypub.signature.result"], + "rejected", + ); + assertEquals( + measurements[0].attributes["http_signatures.failure_reason"], + "invalidSignature", + ); + }, + ); + + await t.step( + "key fetch failure is recorded as result=rejected with failure_reason=keyFetchError", + async () => { + const [meterProvider, recorder] = createTestMeterProvider(); + const keyId = new URL("https://gone.example/actors/alice#main-key"); + const request = await signRequest( + new Request("https://example.com/inbox", { + method: "POST", + headers: { + "Content-Type": "application/activity+json", + accept: "application/ld+json", + }, + body: JSON.stringify({ + "@context": "https://www.w3.org/ns/activitystreams", + type: "Create", + actor: "https://gone.example/actors/alice", + }), + }), + rsaPrivateKey2, + keyId, + ); + + const result = await verifyRequestDetailed(request, { + contextLoader: mockDocumentLoader, + documentLoader(url) { + if (url === keyId.href) { + throw new FetchError( + keyId, + `HTTP 410: ${keyId.href}`, + new Response(null, { status: 410 }), + ); + } + return mockDocumentLoader(url); + }, + meterProvider, + }); + assertFalse(result.verified); + assertEquals(result.reason.type, "keyFetchError"); + + const measurements = recorder.getMeasurements( + "activitypub.signature.verification.duration", + ); + assertEquals(measurements.length, 1); + assertEquals( + measurements[0].attributes["activitypub.signature.result"], + "rejected", + ); + assertEquals( + measurements[0].attributes["http_signatures.failure_reason"], + "keyFetchError", + ); + }, + ); + + await t.step( + "verifyRequest() wrapper emits exactly one measurement, not two", + async () => { + const [meterProvider, recorder] = createTestMeterProvider(); + const request = await buildSignedRequest(); + const key = await verifyRequest(request, { + contextLoader: mockDocumentLoader, + documentLoader: mockDocumentLoader, + meterProvider, + }); + assertExists(key); + assertEquals( + recorder.getMeasurements( + "activitypub.signature.verification.duration", + ).length, + 1, + ); + }, + ); + + await t.step( + "cached-key retry emits one measurement, not two", + async () => { + const [meterProvider, recorder] = createTestMeterProvider(); + // Prime the cache with a wrong key so the verifier fails with the cached + // key and falls through to the fresh-fetch retry path; both attempts + // must collapse to a single measurement. + const cache: Record = { + "https://example.com/key2": rsaPublicKey1, + }; + const request = await buildSignedRequest(); + const key = await verifyRequest(request, { + contextLoader: mockDocumentLoader, + documentLoader: mockDocumentLoader, + meterProvider, + keyCache: { + get(keyId) { + return Promise.resolve(cache[keyId.href]); + }, + set(keyId, k) { + cache[keyId.href] = k; + return Promise.resolve(); + }, + } satisfies KeyCache, + }); + assertExists(key); + assertEquals( + recorder.getMeasurements( + "activitypub.signature.verification.duration", + ).length, + 1, + ); + }, + ); + + await t.step( + "key fetch records result=fetched on a cold cache", + async () => { + const [meterProvider, recorder] = createTestMeterProvider(); + const request = await buildSignedRequest(); + const key = await verifyRequest(request, { + contextLoader: mockDocumentLoader, + documentLoader: mockDocumentLoader, + meterProvider, + }); + assertExists(key); + + const measurements = recorder.getMeasurements( + "activitypub.signature.key_fetch.duration", + ); + assertEquals(measurements.length, 1); + assertEquals(measurements[0].type, "histogram"); + assertGreaterOrEqual(measurements[0].value, 0); + assertEquals( + measurements[0].attributes["activitypub.signature.kind"], + "http", + ); + assertEquals( + measurements[0].attributes[ + "activitypub.signature.key_fetch.result" + ], + "fetched", + ); + }, + ); + + await t.step( + "key fetch records result=hit when served from the key cache", + async () => { + const [meterProvider, recorder] = createTestMeterProvider(); + const cache: Record = { + "https://example.com/key2": rsaPublicKey2, + }; + const request = await buildSignedRequest(); + const key = await verifyRequest(request, { + contextLoader: mockDocumentLoader, + documentLoader: mockDocumentLoader, + meterProvider, + keyCache: { + get(keyId) { + return Promise.resolve(cache[keyId.href]); + }, + set(keyId, k) { + cache[keyId.href] = k; + return Promise.resolve(); + }, + } satisfies KeyCache, + }); + assertExists(key); + + const measurements = recorder.getMeasurements( + "activitypub.signature.key_fetch.duration", + ); + assertEquals(measurements.length, 1); + assertEquals( + measurements[0].attributes[ + "activitypub.signature.key_fetch.result" + ], + "hit", + ); + }, + ); + + await t.step( + "key fetch records result=error when the remote key returns HTTP 410", + async () => { + const [meterProvider, recorder] = createTestMeterProvider(); + const keyId = new URL("https://gone.example/actors/alice#main-key"); + const request = await signRequest( + new Request("https://example.com/inbox", { + method: "POST", + headers: { + "Content-Type": "application/activity+json", + accept: "application/ld+json", + }, + body: "{}", + }), + rsaPrivateKey2, + keyId, + ); + const result = await verifyRequestDetailed(request, { + contextLoader: mockDocumentLoader, + documentLoader(url) { + if (url === keyId.href) { + throw new FetchError( + keyId, + `HTTP 410: ${keyId.href}`, + new Response(null, { status: 410 }), + ); + } + return mockDocumentLoader(url); + }, + meterProvider, + }); + assertFalse(result.verified); + + const measurements = recorder.getMeasurements( + "activitypub.signature.key_fetch.duration", + ); + assertEquals(measurements.length, 1); + assertEquals( + measurements[0].attributes[ + "activitypub.signature.key_fetch.result" + ], + "error", + ); + }, + ); + + await t.step( + "draft-cavage with unknown algorithm omits the algorithm metric attribute", + async () => { + const [meterProvider, recorder] = createTestMeterProvider(); + const result = await verifyRequestDetailed( + new Request("https://example.com/", { + method: "POST", + headers: { + Date: "Tue, 05 Mar 2024 07:49:44 GMT", + Digest: "sha-256=47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=", + Signature: + 'keyId="https://example.com/key2",algorithm="x-attacker-supplied",' + + 'headers="(request-target) date digest",signature="AAAA"', + }, + body: "", + }), + { + documentLoader: mockDocumentLoader, + contextLoader: mockDocumentLoader, + meterProvider, + }, + ); + assertFalse(result.verified); + const measurements = recorder.getMeasurements( + "activitypub.signature.verification.duration", + ); + assertEquals(measurements.length, 1); + assertFalse( + "http_signatures.algorithm" in measurements[0].attributes, + ); + }, + ); +}); + test("signRequest() and verifyRequest() [rfc9421] implementation", async () => { // Create a fixed timestamp and content for consistent testing const currentTimestamp = 1709626184; diff --git a/packages/fedify/src/sig/http.ts b/packages/fedify/src/sig/http.ts index e5457afb8..8b138b457 100644 --- a/packages/fedify/src/sig/http.ts +++ b/packages/fedify/src/sig/http.ts @@ -2,6 +2,7 @@ import { CryptographicKey } from "@fedify/vocab"; import { type DocumentLoader, FetchError } from "@fedify/vocab-runtime"; import { getLogger } from "@logtape/logtape"; import { + type MeterProvider, type Span, SpanStatusCode, trace, @@ -21,6 +22,11 @@ import { Item, } from "structured-field-values"; import metadata from "../../deno.json" with { type: "json" }; +import { + getDurationMs, + getFederationMetrics, + type SignatureVerificationResult, +} from "../federation/metrics.ts"; import { type AcceptSignatureComponent, fulfillAcceptSignature, @@ -653,6 +659,13 @@ export interface VerifyRequestOptions { * @since 1.3.0 */ tracerProvider?: TracerProvider; + + /** + * The OpenTelemetry meter provider. If omitted, the global meter provider + * is used. + * @since 2.3.0 + */ + meterProvider?: MeterProvider; } /** @@ -732,6 +745,68 @@ function getKeyFetchErrorName(error: Error): string { return error.name || error.constructor.name || "Error"; } +interface HttpSignatureMetricsContext { + algorithm?: string; +} + +/** + * Times an awaited public key fetch and records exactly one + * `activitypub.signature.key_fetch.duration` measurement, classifying the + * outcome as `hit`, `fetched`, or `error` based on the `cached` flag and + * whether the returned key is non-null. Errors thrown by the fetch are + * reported as `error` and rethrown, so verifier behavior is unchanged. + */ +async function measureKeyFetch< + T extends { cached: boolean; key?: unknown }, +>( + kind: "http", + meterProvider: MeterProvider | undefined, + fetch: () => Promise, +): Promise { + const start = performance.now(); + try { + const result = await fetch(); + getFederationMetrics(meterProvider).recordSignatureKeyFetchDuration( + getDurationMs(start), + kind, + result.key != null ? (result.cached ? "hit" : "fetched") : "error", + ); + return result; + } catch (error) { + getFederationMetrics(meterProvider).recordSignatureKeyFetchDuration( + getDurationMs(start), + kind, + "error", + ); + throw error; + } +} + +/** + * Known draft-cavage `algorithm` parameter values, used to keep the + * `http_signatures.algorithm` metric attribute on a bounded set. The header + * field is attacker-controlled and not used to select the verification + * algorithm, so unknown values are dropped from the metric to prevent + * cardinality blow-up. + */ +const DRAFT_KNOWN_ALGORITHMS: ReadonlySet = new Set([ + "ecdsa-sha256", + "ecdsa-sha384", + "ecdsa-sha512", + "ed25519", + "hs2019", + "rsa-sha1", + "rsa-sha256", + "rsa-sha512", +]); + +function classifyHttpVerifyResult( + result: VerifyRequestDetailedResult, +): SignatureVerificationResult { + if (result.verified) return "verified"; + return result.reason.type === "noSignature" ? "missing" : "rejected"; +} + function recordVerificationResult( span: Span, result: VerifyRequestDetailedResult, @@ -806,6 +881,10 @@ export async function verifyRequestDetailed( span.setAttribute(ATTR_HTTP_REQUEST_HEADER(name), value); } } + const start = performance.now(); + const metricsContext: HttpSignatureMetricsContext = {}; + let result: VerifyRequestDetailedResult | undefined; + let threw = false; try { // Choose implementation based on spec option let spec = options.spec; @@ -815,11 +894,20 @@ export async function verifyRequestDetailed( : "draft-cavage-http-signatures-12"; } - let result: VerifyRequestDetailedResult; if (spec === "rfc9421") { - result = await verifyRequestRfc9421(request, span, options); + result = await verifyRequestRfc9421( + request, + span, + metricsContext, + options, + ); } else { - result = await verifyRequestDraft(request, span, options); + result = await verifyRequestDraft( + request, + span, + metricsContext, + options, + ); } recordVerificationResult(span, result); @@ -828,12 +916,30 @@ export async function verifyRequestDetailed( } return result; } catch (error) { + threw = true; span.setStatus({ code: SpanStatusCode.ERROR, message: String(error), }); throw error; } finally { + const classified: SignatureVerificationResult = threw + ? "error" + : classifyHttpVerifyResult(result!); + const failureReason = classified === "rejected" && result != null && + !result.verified + ? result.reason.type + : undefined; + getFederationMetrics(options.meterProvider) + .recordSignatureVerificationDuration( + getDurationMs(start), + "http", + classified, + { + algorithm: metricsContext.algorithm, + failureReason, + }, + ); span.end(); } }, @@ -843,12 +949,14 @@ export async function verifyRequestDetailed( async function verifyRequestDraft( request: Request, span: Span, + metricsContext: HttpSignatureMetricsContext, { documentLoader, contextLoader, timeWindow, currentTime, keyCache, + meterProvider, tracerProvider, }: VerifyRequestOptions = {}, ): Promise { @@ -1053,17 +1161,23 @@ async function verifyRequestDraft( span?.setAttribute("http_signatures.key_id", keyId); if ("algorithm" in sigValues) { span?.setAttribute("http_signatures.algorithm", sigValues.algorithm); + const normalizedAlgorithm = sigValues.algorithm.toLowerCase(); + if (DRAFT_KNOWN_ALGORITHMS.has(normalizedAlgorithm)) { + metricsContext.algorithm = normalizedAlgorithm; + } } - const { key, cached, fetchError } = await fetchKeyDetailed( - keyIdUrl, - CryptographicKey, - { - documentLoader, - contextLoader, - keyCache, - tracerProvider, - }, + const fetchResult = await measureKeyFetch( + "http", + meterProvider, + () => + fetchKeyDetailed(keyIdUrl, CryptographicKey, { + documentLoader, + contextLoader, + keyCache, + tracerProvider, + }), ); + const { key, cached, fetchError } = fetchResult; if (fetchError != null) { return keyFetchErrorResult(keyIdUrl, fetchError); } @@ -1115,8 +1229,14 @@ async function verifyRequestDraft( "is invalid. Retrying with the freshly fetched key...", { keyId, signature, message }, ); - return await verifyRequestDetailed( + // Reuse the outer span and metricsContext so the cached-key retry stays + // a single observed verification operation: one `http_signatures.verify` + // span and one `activitypub.signature.verification.duration` measurement + // per public call. + return await verifyRequestDraft( originalRequest, + span, + metricsContext, { documentLoader, contextLoader, @@ -1126,6 +1246,8 @@ async function verifyRequestDraft( get: () => Promise.resolve(undefined), set: async (keyId, key) => await keyCache?.set(keyId, key), }, + meterProvider, + tracerProvider, }, ); } @@ -1210,12 +1332,14 @@ async function verifyRfc9421ContentDigest( async function verifyRequestRfc9421( request: Request, span: Span, + metricsContext: HttpSignatureMetricsContext, { documentLoader, contextLoader, timeWindow, currentTime, keyCache, + meterProvider, tracerProvider, }: VerifyRequestOptions = {}, ): Promise { @@ -1275,12 +1399,29 @@ async function verifyRequestRfc9421( } let failure: VerifyRequestDetailedResult = noSignatureResult(); + // Tracks the bounded algorithm of the candidate that ended up as the final + // `failure`, so a histogram measurement records the algorithm of the + // signature actually returned rather than an earlier candidate that + // happened to carry a bounded algorithm but was overwritten by a later + // unsupported candidate. + let failureAlgorithm: string | undefined; + + // `setFailure` keeps the failure result and its bounded algorithm in sync; + // every continue-out-of-iteration path goes through it so a later candidate + // cannot inherit an earlier candidate's algorithm. + const setFailure = ( + result: VerifyRequestDetailedResult, + algorithm?: string, + ): void => { + failure = result; + failureAlgorithm = algorithm; + }; for (const sigName of signatureNames) { // Skip if we don't have the signature bytes if (!signatures[sigName]) { - failure = invalidSignatureResult( - parseKeyId(signatureInputs[sigName]?.keyId), + setFailure( + invalidSignatureResult(parseKeyId(signatureInputs[sigName]?.keyId)), ); continue; } @@ -1295,7 +1436,7 @@ async function verifyRequestRfc9421( "Failed to verify; missing keyId in signature {signatureName}.", { signatureName: sigName, signatureInput: signatureInputHeader }, ); - failure = invalidSignatureResult(null); + setFailure(invalidSignatureResult(null)); continue; } @@ -1304,7 +1445,7 @@ async function verifyRequestRfc9421( "Failed to verify; missing created timestamp in signature {signatureName}.", { signatureName: sigName, signatureInput: signatureInputHeader }, ); - failure = invalidSignatureResult(keyId); + setFailure(invalidSignatureResult(keyId)); continue; } @@ -1322,7 +1463,7 @@ async function verifyRequestRfc9421( "Failed to verify; signature created time is too far in the future.", { created: signatureCreated.toString(), now: now.toString() }, ); - failure = invalidSignatureResult(keyId); + setFailure(invalidSignatureResult(keyId)); continue; } else if ( Temporal.Instant.compare(signatureCreated, now.subtract(tw)) < 0 @@ -1331,7 +1472,7 @@ async function verifyRequestRfc9421( "Failed to verify; signature created time is too far in the past.", { created: signatureCreated.toString(), now: now.toString() }, ); - failure = invalidSignatureResult(keyId); + setFailure(invalidSignatureResult(keyId)); continue; } } @@ -1348,7 +1489,7 @@ async function verifyRequestRfc9421( "Failed to verify; Content-Digest header required but not found.", { components: sigInput.components }, ); - failure = invalidSignatureResult(keyId); + setFailure(invalidSignatureResult(keyId)); continue; } @@ -1363,7 +1504,7 @@ async function verifyRequestRfc9421( "Failed to verify; Content-Digest verification failed.", { contentDigest: contentDigestHeader }, ); - failure = invalidSignatureResult(keyId); + setFailure(invalidSignatureResult(keyId)); continue; } } @@ -1372,28 +1513,30 @@ async function verifyRequestRfc9421( span?.setAttribute("http_signatures.key_id", sigInput.keyId); span?.setAttribute("http_signatures.created", sigInput.created.toString()); if (keyId == null) { - failure = invalidSignatureResult(null); + setFailure(invalidSignatureResult(null)); continue; } - const { key, cached, fetchError } = await fetchKeyDetailed( - keyId, - CryptographicKey, - { - documentLoader, - contextLoader, - keyCache, - tracerProvider, - }, + const rfcFetchResult = await measureKeyFetch( + "http", + meterProvider, + () => + fetchKeyDetailed(keyId, CryptographicKey, { + documentLoader, + contextLoader, + keyCache, + tracerProvider, + }), ); + const { key, cached, fetchError } = rfcFetchResult; if (fetchError != null) { - failure = keyFetchErrorResult(keyId, fetchError); + setFailure(keyFetchErrorResult(keyId, fetchError)); continue; } if (!key) { logger.debug("Failed to fetch key: {keyId}", { keyId: sigInput.keyId }); - failure = invalidSignatureResult(keyId); + setFailure(invalidSignatureResult(keyId)); continue; } @@ -1417,8 +1560,14 @@ async function verifyRequestRfc9421( alg = "ed25519"; } } - if (alg) span?.setAttribute("http_signatures.algorithm", alg); + if (alg) { + span?.setAttribute("http_signatures.algorithm", alg); + } const algorithm = alg && rfc9421AlgorithmMap[alg]; + // Only record the algorithm metric attribute after the value matches the + // RFC 9421 algorithm map, so attacker-supplied `alg` strings cannot + // inflate `http_signatures.algorithm` cardinality. + const candidateAlgorithm = algorithm ? alg : undefined; if (!algorithm) { logger.debug( "Failed to verify; unsupported algorithm: {algorithm}", @@ -1427,7 +1576,7 @@ async function verifyRequestRfc9421( supported: Object.keys(rfc9421AlgorithmMap), }, ); - failure = invalidSignatureResult(keyId); + setFailure(invalidSignatureResult(keyId)); continue; } @@ -1444,7 +1593,7 @@ async function verifyRequestRfc9421( "Failed to create signature base for verification: {error}", { error, signatureInput: sigInput }, ); - failure = invalidSignatureResult(keyId); + setFailure(invalidSignatureResult(keyId), candidateAlgorithm); continue; } const signatureBaseBytes = new TextEncoder().encode(signatureBase); @@ -1461,6 +1610,7 @@ async function verifyRequestRfc9421( ); if (verified) { + metricsContext.algorithm = candidateAlgorithm; return { verified: true, key, signatureLabel: sigName }; } else if (cached) { // If we used a cached key and verification failed, try fetching fresh key @@ -1469,8 +1619,15 @@ async function verifyRequestRfc9421( { keyId: sigInput.keyId }, ); - return await verifyRequestDetailed( + // Reuse the outer span and metricsContext so the cached-key retry + // stays a single observed verification operation: one + // `http_signatures.verify` span and one + // `activitypub.signature.verification.duration` measurement per + // public call. + return await verifyRequestRfc9421( originalRequest, + span, + metricsContext, { documentLoader, contextLoader, @@ -1481,6 +1638,8 @@ async function verifyRequestRfc9421( set: async (keyId, key) => await keyCache?.set(keyId, key), }, spec: "rfc9421", + meterProvider, + tracerProvider, }, ); } else { @@ -1488,17 +1647,18 @@ async function verifyRequestRfc9421( "Failed to verify signature with fetched key {keyId}; signature invalid.", { keyId: sigInput.keyId, signatureBase }, ); - failure = invalidSignatureResult(keyId); + setFailure(invalidSignatureResult(keyId), candidateAlgorithm); } } catch (error) { logger.debug( "Error during signature verification: {error}", { error, keyId: sigInput.keyId, algorithm: sigInput.alg }, ); - failure = invalidSignatureResult(keyId); + setFailure(invalidSignatureResult(keyId), candidateAlgorithm); } } + metricsContext.algorithm = failureAlgorithm; return failure; } diff --git a/packages/fedify/src/sig/ld.test.ts b/packages/fedify/src/sig/ld.test.ts index b6db88171..ed971eb29 100644 --- a/packages/fedify/src/sig/ld.test.ts +++ b/packages/fedify/src/sig/ld.test.ts @@ -1,8 +1,13 @@ -import { mockDocumentLoader, test } from "@fedify/fixture"; +import { + createTestMeterProvider, + mockDocumentLoader, + test, +} from "@fedify/fixture"; import { CryptographicKey } from "@fedify/vocab"; import { assert } from "@std/assert/assert"; import { assertEquals } from "@std/assert/assert-equals"; import { assertFalse } from "@std/assert/assert-false"; +import { assertGreaterOrEqual } from "@std/assert/assert-greater-or-equal"; import { assertRejects } from "@std/assert/assert-rejects"; import { assertThrows } from "@std/assert/assert-throws"; import { encodeBase64 } from "byte-encodings/base64"; @@ -338,4 +343,237 @@ test("verifyJsonLd()", async () => { assertFalse(verified2); }); +test("verifyJsonLd() records verification duration metric", async (t) => { + await t.step( + "verified path records result=verified with bounded type", + async () => { + const [meterProvider, recorder] = createTestMeterProvider(); + const verified = await verifyJsonLd(testVector, { + documentLoader: mockDocumentLoader, + contextLoader: mockDocumentLoader, + meterProvider, + }); + assert(verified); + + const measurements = recorder.getMeasurements( + "activitypub.signature.verification.duration", + ); + assertEquals(measurements.length, 1); + const m = measurements[0]; + assertEquals(m.type, "histogram"); + assertGreaterOrEqual(m.value, 0); + assertEquals(m.attributes["activitypub.signature.kind"], "linked_data"); + assertEquals(m.attributes["activitypub.signature.result"], "verified"); + assertEquals(m.attributes["ld_signatures.type"], "RsaSignature2017"); + }, + ); + + await t.step( + "missing signature records result=missing without type", + async () => { + const [meterProvider, recorder] = createTestMeterProvider(); + const verified = await verifyJsonLd(document, { + documentLoader: mockDocumentLoader, + contextLoader: mockDocumentLoader, + meterProvider, + }); + assertFalse(verified); + + const measurements = recorder.getMeasurements( + "activitypub.signature.verification.duration", + ); + assertEquals(measurements.length, 1); + assertEquals( + measurements[0].attributes["activitypub.signature.kind"], + "linked_data", + ); + assertEquals( + measurements[0].attributes["activitypub.signature.result"], + "missing", + ); + assertFalse("ld_signatures.type" in measurements[0].attributes); + }, + ); + + await t.step("invalid signature records result=rejected", async () => { + const [meterProvider, recorder] = createTestMeterProvider(); + const tampered = { + ...testVector, + signature: { + ...testVector.signature, + signatureValue: encodeBase64(new Uint8Array([1, 2, 3, 4])), + }, + }; + const verified = await verifyJsonLd(tampered, { + documentLoader: mockDocumentLoader, + contextLoader: mockDocumentLoader, + meterProvider, + }); + assertFalse(verified); + + const measurements = recorder.getMeasurements( + "activitypub.signature.verification.duration", + ); + assertEquals(measurements.length, 1); + assertEquals( + measurements[0].attributes["activitypub.signature.result"], + "rejected", + ); + assertEquals( + measurements[0].attributes["ld_signatures.type"], + "RsaSignature2017", + ); + }); + + await t.step( + "malformed (null) signature property records result=rejected, not missing", + async () => { + const [meterProvider, recorder] = createTestMeterProvider(); + const malformed = { ...document, signature: null }; + const verified = await verifyJsonLd(malformed, { + documentLoader: mockDocumentLoader, + contextLoader: mockDocumentLoader, + meterProvider, + }); + assertFalse(verified); + + const measurements = recorder.getMeasurements( + "activitypub.signature.verification.duration", + ); + assertEquals(measurements.length, 1); + assertEquals( + measurements[0].attributes["activitypub.signature.result"], + "rejected", + ); + assertFalse("ld_signatures.type" in measurements[0].attributes); + }, + ); + + await t.step( + "key fetch records result=fetched on a cold cache", + async () => { + const [meterProvider, recorder] = createTestMeterProvider(); + const verified = await verifyJsonLd(testVector, { + documentLoader: mockDocumentLoader, + contextLoader: mockDocumentLoader, + meterProvider, + }); + assert(verified); + + const measurements = recorder.getMeasurements( + "activitypub.signature.key_fetch.duration", + ); + assertEquals(measurements.length, 1); + assertGreaterOrEqual(measurements[0].value, 0); + assertEquals( + measurements[0].attributes["activitypub.signature.kind"], + "linked_data", + ); + assertEquals( + measurements[0].attributes[ + "activitypub.signature.key_fetch.result" + ], + "fetched", + ); + }, + ); + + await t.step( + "missing signature emits no key_fetch measurement", + async () => { + const [meterProvider, recorder] = createTestMeterProvider(); + const verified = await verifyJsonLd(document, { + documentLoader: mockDocumentLoader, + contextLoader: mockDocumentLoader, + meterProvider, + }); + assertFalse(verified); + + assertEquals( + recorder.getMeasurements( + "activitypub.signature.key_fetch.duration", + ).length, + 0, + ); + }, + ); + + await t.step( + "cached-key retry emits two key_fetch measurements: hit then fetched", + async () => { + const [meterProvider, recorder] = createTestMeterProvider(); + // Prime the cache with a wrong-but-valid RSA key for the signer's + // keyId. The first verification attempt uses the stale cached key, + // fails, and falls through to the fresh-fetch retry path inside + // `verifySignature()`. The retry must record its own key_fetch + // measurement separately from the cached attempt. + const verified = await verifyJsonLd(testVector, { + documentLoader: mockDocumentLoader, + contextLoader: mockDocumentLoader, + meterProvider, + keyCache: { + async get(keyId: URL) { + return new CryptographicKey({ + id: keyId, + owner: new URL( + "https://activitypub.academy/users/brauca_darradiul", + ), + publicKey: + (await generateCryptoKeyPair("RSASSA-PKCS1-v1_5")).publicKey, + }); + }, + set(_keyId: URL, _key: CryptographicKey) { + return Promise.resolve(); + }, + }, + }); + assert(verified); + + const measurements = recorder.getMeasurements( + "activitypub.signature.key_fetch.duration", + ); + assertEquals(measurements.length, 2); + assertEquals( + measurements[0].attributes[ + "activitypub.signature.key_fetch.result" + ], + "hit", + ); + assertEquals( + measurements[1].attributes[ + "activitypub.signature.key_fetch.result" + ], + "fetched", + ); + }, + ); + + await t.step( + "unknown signature type omits the ld_signatures.type metric attribute", + async () => { + const [meterProvider, recorder] = createTestMeterProvider(); + const exotic = { + ...testVector, + signature: { ...testVector.signature, type: "MadeUpSignature9999" }, + }; + const verified = await verifyJsonLd(exotic, { + documentLoader: mockDocumentLoader, + contextLoader: mockDocumentLoader, + meterProvider, + }); + assertFalse(verified); + + const measurements = recorder.getMeasurements( + "activitypub.signature.verification.duration", + ); + assertEquals(measurements.length, 1); + assertEquals( + measurements[0].attributes["activitypub.signature.result"], + "rejected", + ); + assertFalse("ld_signatures.type" in measurements[0].attributes); + }, + ); +}); + // cSpell: ignore ostatus diff --git a/packages/fedify/src/sig/ld.ts b/packages/fedify/src/sig/ld.ts index 3a6c01554..8b671f2f5 100644 --- a/packages/fedify/src/sig/ld.ts +++ b/packages/fedify/src/sig/ld.ts @@ -2,10 +2,20 @@ import { Activity, CryptographicKey, getTypeId, Object } from "@fedify/vocab"; import { type DocumentLoader, getDocumentLoader } from "@fedify/vocab-runtime"; import jsonld from "@fedify/vocab-runtime/jsonld"; import { getLogger } from "@logtape/logtape"; -import { SpanStatusCode, trace, type TracerProvider } from "@opentelemetry/api"; +import { + type MeterProvider, + SpanStatusCode, + trace, + type TracerProvider, +} from "@opentelemetry/api"; import { decodeBase64, encodeBase64 } from "byte-encodings/base64"; import { encodeHex } from "byte-encodings/hex"; import metadata from "../../deno.json" with { type: "json" }; +import { + getDurationMs, + getFederationMetrics, + type SignatureVerificationResult, +} from "../federation/metrics.ts"; import { fetchKey, type KeyCache, validateCryptoKey } from "./key.ts"; const logger = getLogger(["fedify", "sig", "ld"]); @@ -275,6 +285,13 @@ export interface VerifySignatureOptions { * @since 1.3.0 */ tracerProvider?: TracerProvider; + + /** + * The OpenTelemetry meter provider. If omitted, the global meter provider + * is used. + * @since 2.3.0 + */ + meterProvider?: MeterProvider; } /** @@ -301,10 +318,9 @@ export async function verifySignature( ); return null; } - const { key, cached } = await fetchKey( - new URL(sig.creator), - CryptographicKey, - options, + const { key, cached } = await measureLdKeyFetch( + options.meterProvider, + () => fetchKey(new URL(sig.creator), CryptographicKey, options), ); if (key == null) return null; const sigOpts: { @@ -358,16 +374,16 @@ export async function verifySignature( "Retrying with the freshly fetched key...", { keyId: sig.creator, ...sig }, ); - const { key } = await fetchKey( - new URL(sig.creator), - CryptographicKey, - { - ...options, - keyCache: { - get: () => Promise.resolve(undefined), - set: async (keyId, key) => await options.keyCache?.set(keyId, key), - }, - }, + const { key } = await measureLdKeyFetch( + options.meterProvider, + () => + fetchKey(new URL(sig.creator), CryptographicKey, { + ...options, + keyCache: { + get: () => Promise.resolve(undefined), + set: async (keyId, key) => await options.keyCache?.set(keyId, key), + }, + }), ); if (key == null) return null; const verified = await crypto.subtle.verify( @@ -394,6 +410,73 @@ export async function verifySignature( export interface VerifyJsonLdOptions extends VerifySignatureOptions { } +/** + * Times an awaited public key fetch and records exactly one + * `activitypub.signature.key_fetch.duration` measurement, classifying the + * outcome as `hit`, `fetched`, or `error` based on the `cached` flag and + * whether the returned key is non-null. Errors thrown by the fetch are + * reported as `error` and rethrown, so verifier behavior is unchanged. + */ +async function measureLdKeyFetch< + T extends { cached: boolean; key: CryptographicKey | null }, +>( + meterProvider: MeterProvider | undefined, + fetch: () => Promise, +): Promise { + const start = performance.now(); + try { + const result = await fetch(); + getFederationMetrics(meterProvider).recordSignatureKeyFetchDuration( + getDurationMs(start), + "linked_data", + result.key != null ? (result.cached ? "hit" : "fetched") : "error", + ); + return result; + } catch (error) { + getFederationMetrics(meterProvider).recordSignatureKeyFetchDuration( + getDurationMs(start), + "linked_data", + "error", + ); + throw error; + } +} + +/** + * Known Linked Data Signature `type` values, used to keep + * `ld_signatures.type` on a bounded set of spec-defined string values. + * Fedify only signs and verifies `RsaSignature2017`; other values come in + * only from external documents and are dropped from the metric attribute to + * avoid attacker-controlled cardinality. + */ +const LD_KNOWN_SIGNATURE_TYPES: ReadonlySet = new Set([ + "RsaSignature2017", +]); + +function hasLdSignatureProperty(jsonLd: unknown): boolean { + return ( + typeof jsonLd === "object" && jsonLd != null && "signature" in jsonLd + ); +} + +function getLdSignatureObject( + jsonLd: unknown, +): Record | undefined { + if ( + typeof jsonLd !== "object" || jsonLd == null || !("signature" in jsonLd) + ) { + return undefined; + } + const { signature } = jsonLd as { signature: unknown }; + if ( + typeof signature !== "object" || signature == null || + Array.isArray(signature) + ) { + return undefined; + } + return signature as Record; +} + /** * Verify the authenticity of the given JSON-LD document using Linked Data * Signatures. If the document is signed, this function verifies the signature @@ -412,40 +495,33 @@ export async function verifyJsonLd( return await tracer.startActiveSpan( "ld_signatures.verify", async (span) => { + const start = performance.now(); + let verified = false; + let threw = false; + let signatureType: string | undefined; + // A `signature` property being present at all (even if it is `null` or a + // primitive) counts as "had signature" for classification, so malformed + // signatures are reported as `rejected` rather than as `missing`. + const hadSignature = hasLdSignatureProperty(jsonLd); try { const object = await Object.fromJsonLd(jsonLd, options); if (object.id != null) { span.setAttribute("activitypub.object.id", object.id.href); } span.setAttribute("activitypub.object.type", getTypeId(object).href); - if ( - typeof jsonLd === "object" && jsonLd != null && - "signature" in jsonLd && typeof jsonLd.signature === "object" && - jsonLd.signature != null - ) { - if ( - "creator" in jsonLd.signature && - typeof jsonLd.signature.creator === "string" - ) { - span.setAttribute( - "ld_signatures.key_id", - jsonLd.signature.creator, - ); + const sig = getLdSignatureObject(jsonLd); + if (sig != null) { + if (typeof sig.creator === "string") { + span.setAttribute("ld_signatures.key_id", sig.creator); } - if ( - "signatureValue" in jsonLd.signature && - typeof jsonLd.signature.signatureValue === "string" - ) { - span.setAttribute( - "ld_signatures.signature", - jsonLd.signature.signatureValue, - ); + if (typeof sig.signatureValue === "string") { + span.setAttribute("ld_signatures.signature", sig.signatureValue); } - if ( - "type" in jsonLd.signature && - typeof jsonLd.signature.type === "string" - ) { - span.setAttribute("ld_signatures.type", jsonLd.signature.type); + if (typeof sig.type === "string") { + span.setAttribute("ld_signatures.type", sig.type); + if (LD_KNOWN_SIGNATURE_TYPES.has(sig.type)) { + signatureType = sig.type; + } } } const attributions = new Set( @@ -469,14 +545,30 @@ export async function verifyJsonLd( ); return false; } + verified = true; return true; } catch (error) { + threw = true; span.setStatus({ code: SpanStatusCode.ERROR, message: String(error), }); throw error; } finally { + const classified: SignatureVerificationResult = threw + ? "error" + : verified + ? "verified" + : hadSignature + ? "rejected" + : "missing"; + getFederationMetrics(options.meterProvider) + .recordSignatureVerificationDuration( + getDurationMs(start), + "linked_data", + classified, + { ldType: signatureType }, + ); span.end(); } }, diff --git a/packages/fedify/src/sig/proof.test.ts b/packages/fedify/src/sig/proof.test.ts index f7375d32d..d307c87f4 100644 --- a/packages/fedify/src/sig/proof.test.ts +++ b/packages/fedify/src/sig/proof.test.ts @@ -1,4 +1,8 @@ -import { mockDocumentLoader, test } from "@fedify/fixture"; +import { + createTestMeterProvider, + mockDocumentLoader, + test, +} from "@fedify/fixture"; import { normalizeOutgoingActivityJsonLd } from "../compat/outgoing-jsonld.ts"; import { Create, @@ -15,6 +19,7 @@ import { assert, assertEquals, assertFalse, + assertGreaterOrEqual, assertInstanceOf, assertRejects, } from "@std/assert"; @@ -563,6 +568,295 @@ test("verifyProof()", async () => { assertFalse(contextLoaderCalls.includes("https://attacker.example/ctx")); }); +test("verifyProof() records verification duration metric", async (t) => { + const jsonLd = { + "@context": [ + "https://www.w3.org/ns/activitystreams", + "https://w3id.org/security/data-integrity/v1", + ], + id: "https://server.example/activities/1", + type: "Create", + actor: "https://server.example/users/alice", + object: { + id: "https://server.example/objects/1", + type: "Note", + attributedTo: "https://server.example/users/alice", + content: "Hello world", + location: { + type: "Place", + longitude: -71.184902, + latitude: 25.273962, + }, + }, + }; + const proof = new DataIntegrityProof({ + cryptosuite: "eddsa-jcs-2022", + verificationMethod: new URL( + "https://server.example/users/alice#ed25519-key", + ), + proofPurpose: "assertionMethod", + proofValue: decodeMultibase( + // cSpell: disable + "zLaewdp4H9kqtwyrLatK4cjY5oRHwVcw4gibPSUDYDMhi4M49v8pcYk3ZB6D69dNpAPbUmY8ocuJ3m9KhKJEEg7z", + // cSpell: enable + ), + created: Temporal.Instant.from("2023-02-24T23:36:38Z"), + }); + + await t.step( + "verified path records result=verified with bounded cryptosuite", + async () => { + const [meterProvider, recorder] = createTestMeterProvider(); + const key = await verifyProof(jsonLd, proof, { + documentLoader: mockDocumentLoader, + contextLoader: mockDocumentLoader, + meterProvider, + }); + assert(key != null); + + const measurements = recorder.getMeasurements( + "activitypub.signature.verification.duration", + ); + assertEquals(measurements.length, 1); + const m = measurements[0]; + assertEquals(m.type, "histogram"); + assertGreaterOrEqual(m.value, 0); + assertEquals( + m.attributes["activitypub.signature.kind"], + "object_integrity", + ); + assertEquals(m.attributes["activitypub.signature.result"], "verified"); + assertEquals( + m.attributes["object_integrity_proofs.cryptosuite"], + "eddsa-jcs-2022", + ); + }, + ); + + await t.step("rejected path records result=rejected", async () => { + const [meterProvider, recorder] = createTestMeterProvider(); + const tampered = { + ...jsonLd, + object: { ...jsonLd.object, content: "bye" }, + }; + const key = await verifyProof(tampered, proof, { + documentLoader: mockDocumentLoader, + contextLoader: mockDocumentLoader, + meterProvider, + }); + assertEquals(key, null); + + const measurements = recorder.getMeasurements( + "activitypub.signature.verification.duration", + ); + assertEquals(measurements.length, 1); + assertEquals( + measurements[0].attributes["activitypub.signature.result"], + "rejected", + ); + assertEquals( + measurements[0].attributes["object_integrity_proofs.cryptosuite"], + "eddsa-jcs-2022", + ); + }); + + await t.step("cached-key retry emits one measurement, not two", async () => { + const [meterProvider, recorder] = createTestMeterProvider(); + const keyId = "https://server.example/users/alice#ed25519-key"; + // Prime the cache with a different valid Ed25519 Multikey for the same + // keyId. fetchKey returns it as cached=true, the Ed25519 algorithm + // check passes, and verification fails because the key doesn't match + // the proof, so verifyProofInternal goes through its + // "signature failed with cached key" recursive retry. + const cache: Record = { + [keyId]: ed25519Multikey, + }; + const key = await verifyProof(jsonLd, proof, { + documentLoader: mockDocumentLoader, + contextLoader: mockDocumentLoader, + meterProvider, + keyCache: { + get(id) { + return Promise.resolve(cache[id.href]); + }, + set(id, k) { + cache[id.href] = k; + return Promise.resolve(); + }, + } satisfies KeyCache, + }); + assert(key != null); + assertEquals( + recorder.getMeasurements( + "activitypub.signature.verification.duration", + ).length, + 1, + ); + // The retry path is observable as a per-fetch sequence on + // `activitypub.signature.key_fetch.duration`: a `hit` for the stale + // cached attempt, then a `fetched` for the fresh refetch. Mirrors the + // LD cached-key retry test. + const keyFetches = recorder.getMeasurements( + "activitypub.signature.key_fetch.duration", + ); + assertEquals(keyFetches.length, 2); + assertEquals( + keyFetches[0].attributes["activitypub.signature.key_fetch.result"], + "hit", + ); + assertEquals( + keyFetches[1].attributes["activitypub.signature.key_fetch.result"], + "fetched", + ); + }); + + await t.step( + "key fetch records result=fetched on a cold cache", + async () => { + const [meterProvider, recorder] = createTestMeterProvider(); + const key = await verifyProof(jsonLd, proof, { + documentLoader: mockDocumentLoader, + contextLoader: mockDocumentLoader, + meterProvider, + }); + assert(key != null); + + const measurements = recorder.getMeasurements( + "activitypub.signature.key_fetch.duration", + ); + assertEquals(measurements.length, 1); + assertGreaterOrEqual(measurements[0].value, 0); + assertEquals( + measurements[0].attributes["activitypub.signature.kind"], + "object_integrity", + ); + assertEquals( + measurements[0].attributes[ + "activitypub.signature.key_fetch.result" + ], + "fetched", + ); + }, + ); + + await t.step( + "key fetch records result=hit when served from the key cache", + async () => { + const [meterProvider, recorder] = createTestMeterProvider(); + const expectedKey = new Multikey({ + id: new URL("https://server.example/users/alice#ed25519-key"), + controller: new URL("https://server.example/users/alice"), + publicKey: await importMultibaseKey( + "z6MkrJVnaZkeFzdQyMZu1cgjg7k1pZZ6pvBQ7XJPt4swbTQ2", + ), + }); + const cache: Record = { + "https://server.example/users/alice#ed25519-key": expectedKey, + }; + const key = await verifyProof(jsonLd, proof, { + documentLoader: mockDocumentLoader, + contextLoader: mockDocumentLoader, + meterProvider, + keyCache: { + get(id) { + return Promise.resolve(cache[id.href]); + }, + set(id, k) { + cache[id.href] = k; + return Promise.resolve(); + }, + } satisfies KeyCache, + }); + assert(key != null); + + const measurements = recorder.getMeasurements( + "activitypub.signature.key_fetch.duration", + ); + assertEquals(measurements.length, 1); + assertEquals( + measurements[0].attributes[ + "activitypub.signature.key_fetch.result" + ], + "hit", + ); + }, + ); + + await t.step( + "verifyObject() wrapper emits one measurement per inner verifyProof()", + async () => { + const [meterProvider, recorder] = createTestMeterProvider(); + const create = await verifyObject(Create, { + ...jsonLd, + proof: await proof.toJsonLd({ + format: "compact", + contextLoader: mockDocumentLoader, + }), + }, { + documentLoader: mockDocumentLoader, + contextLoader: mockDocumentLoader, + meterProvider, + }); + assert(create != null); + // The fixture has exactly one proof; the wrapper should not + // double-instrument. + assertEquals( + recorder.getMeasurements( + "activitypub.signature.verification.duration", + ).length, + 1, + ); + }, + ); + + await t.step( + "unknown cryptosuite omits the cryptosuite metric attribute", + async () => { + const [meterProvider, recorder] = createTestMeterProvider(); + // `DataIntegrityProof`'s constructor and `clone()` reject any + // cryptosuite other than `eddsa-jcs-2022`, but `fromJsonLd()` does + // not, so build the exotic proof through the JSON-LD path to + // exercise the metric attribute whitelist on an inbound proof that + // the validator would later reject. + const exoticProof = await DataIntegrityProof.fromJsonLd({ + "@context": "https://w3id.org/security/data-integrity/v1", + type: "DataIntegrityProof", + cryptosuite: "made-up-suite-9999", + verificationMethod: "https://server.example/users/alice#ed25519-key", + proofPurpose: "assertionMethod", + proofValue: + // cSpell: disable + "zLaewdp4H9kqtwyrLatK4cjY5oRHwVcw4gibPSUDYDMhi4M49v8pcYk3ZB6D69dNpAPbUmY8ocuJ3m9KhKJEEg7z", + // cSpell: enable + created: "2023-02-24T23:36:38Z", + }, { + documentLoader: mockDocumentLoader, + contextLoader: mockDocumentLoader, + }); + assertEquals(exoticProof.cryptosuite, "made-up-suite-9999"); + + const key = await verifyProof(jsonLd, exoticProof, { + documentLoader: mockDocumentLoader, + contextLoader: mockDocumentLoader, + meterProvider, + }); + assertEquals(key, null); + + const measurements = recorder.getMeasurements( + "activitypub.signature.verification.duration", + ); + assertEquals(measurements.length, 1); + assertEquals( + measurements[0].attributes["activitypub.signature.result"], + "rejected", + ); + assertFalse( + "object_integrity_proofs.cryptosuite" in measurements[0].attributes, + ); + }, + ); +}); + test("verifyObject()", async () => { const options: VerifyObjectOptions = { documentLoader: mockDocumentLoader, diff --git a/packages/fedify/src/sig/proof.ts b/packages/fedify/src/sig/proof.ts index cb7885631..3a1ef11c9 100644 --- a/packages/fedify/src/sig/proof.ts +++ b/packages/fedify/src/sig/proof.ts @@ -7,12 +7,22 @@ import { } from "@fedify/vocab"; import type { DocumentLoader } from "@fedify/vocab-runtime"; import { getLogger } from "@logtape/logtape"; -import { SpanStatusCode, trace, type TracerProvider } from "@opentelemetry/api"; +import { + type MeterProvider, + SpanStatusCode, + trace, + type TracerProvider, +} from "@opentelemetry/api"; import { encodeHex } from "byte-encodings/hex"; import serialize from "json-canon"; import metadata from "../../deno.json" with { type: "json" }; import { normalizeOutgoingActivityJsonLd } from "../compat/outgoing-jsonld.ts"; import { preloadedOnlyDocumentLoader } from "../compat/preloaded-context-loader.ts"; +import { + getDurationMs, + getFederationMetrics, + type SignatureVerificationResult, +} from "../federation/metrics.ts"; import { fetchKey, type FetchKeyResult, @@ -20,6 +30,57 @@ import { validateCryptoKey, } from "./key.ts"; +/** + * Known Object Integrity Proof `cryptosuite` values, used to keep + * `object_integrity_proofs.cryptosuite` on a bounded set of spec-defined + * string values. Fedify currently signs and verifies only + * `eddsa-jcs-2022`; other values come in only from external proofs and are + * dropped from the metric attribute to avoid attacker-controlled + * cardinality. + */ +const OIP_KNOWN_CRYPTOSUITES: ReadonlySet = new Set([ + "eddsa-jcs-2022", +]); + +/** + * Times an awaited public key fetch and records exactly one + * `activitypub.signature.key_fetch.duration` measurement, classifying the + * outcome as `hit`, `fetched`, or `error` based on the `cached` flag and + * whether the returned key is non-null. Errors thrown by the fetch are + * reported as `error` and rethrown, so verifier behavior is unchanged. + * + * The fetch is wrapped in its own async timer so the recorded duration + * covers only the key fetch itself, not the surrounding JCS canonicalization + * and SHA-256 digest work that runs concurrently in + * {@link verifyProofInternal}. + */ +async function measureOipKeyFetch( + meterProvider: MeterProvider | undefined, + fetch: () => Promise>, +): Promise> { + const start = performance.now(); + // The fetch closure is invoked synchronously here (before the first + // `await`), so the timing window stays tight and the caller still gets a + // Promise it can hold while running other work concurrently. + const pending = fetch(); + try { + const result = await pending; + getFederationMetrics(meterProvider).recordSignatureKeyFetchDuration( + getDurationMs(start), + "object_integrity", + result.key != null ? (result.cached ? "hit" : "fetched") : "error", + ); + return result; + } catch (error) { + getFederationMetrics(meterProvider).recordSignatureKeyFetchDuration( + getDurationMs(start), + "object_integrity", + "error", + ); + throw error; + } +} + const logger = getLogger(["fedify", "sig", "proof"]); /** @@ -276,6 +337,13 @@ export interface VerifyProofOptions { * @since 1.3.0 */ tracerProvider?: TracerProvider; + + /** + * The OpenTelemetry meter provider. If omitted, the global meter provider + * is used. + * @since 2.3.0 + */ + meterProvider?: MeterProvider; } /** @@ -298,6 +366,13 @@ export async function verifyProof( return await tracer.startActiveSpan( "object_integrity_proofs.verify", async (span) => { + const start = performance.now(); + let verified = false; + let threw = false; + const cryptosuite = proof.cryptosuite != null && + OIP_KNOWN_CRYPTOSUITES.has(proof.cryptosuite) + ? proof.cryptosuite + : undefined; if (span.isRecording()) { if (proof.cryptosuite != null) { span.setAttribute( @@ -321,14 +396,28 @@ export async function verifyProof( try { const key = await verifyProofInternal(jsonLd, proof, options); if (key == null) span.setStatus({ code: SpanStatusCode.ERROR }); + else verified = true; return key; } catch (error) { + threw = true; span.setStatus({ code: SpanStatusCode.ERROR, message: String(error), }); throw error; } finally { + const classified: SignatureVerificationResult = threw + ? "error" + : verified + ? "verified" + : "rejected"; + getFederationMetrics(options.meterProvider) + .recordSignatureVerificationDuration( + getDurationMs(start), + "object_integrity", + classified, + { cryptosuite }, + ); span.end(); } }, @@ -350,10 +439,9 @@ async function verifyProofInternal( proof.proofValue == null || proof.created == null ) return null; - const publicKeyPromise = fetchKey( - proof.verificationMethodId, - Multikey, - options, + const publicKeyPromise = measureOipKeyFetch( + options.meterProvider, + () => fetchKey(proof.verificationMethodId!, Multikey, options), ); const proofConfig = { // deno-lint-ignore no-explicit-any @@ -411,7 +499,10 @@ async function verifyProofInternal( "Ed25519 key:\n{keyId}; retrying with the freshly fetched key...", { proof, keyId: proof.verificationMethodId.href }, ); - return await verifyProof(jsonLd, proof, { + // Recurse into `verifyProofInternal()` (not `verifyProof()`) so the + // retry reuses the outer `object_integrity_proofs.verify` span and + // `activitypub.signature.verification.duration` measurement. + return await verifyProofInternal(jsonLd, proof, { ...options, keyCache: { // Returning `undefined` signals "nothing cached" and forces @@ -467,7 +558,10 @@ async function verifyProofInternal( "with the freshly fetched key...", { keyId: proof.verificationMethodId.href, proof }, ); - return await verifyProof(jsonLd, proof, { + // Recurse into `verifyProofInternal()` (not `verifyProof()`) so the + // retry reuses the outer `object_integrity_proofs.verify` span and + // `activitypub.signature.verification.duration` measurement. + return await verifyProofInternal(jsonLd, proof, { ...options, keyCache: { get: () => Promise.resolve(undefined),