diff --git a/docs/README.md b/docs/README.md index 59fe04938b..16e0f4c458 100644 --- a/docs/README.md +++ b/docs/README.md @@ -16,6 +16,7 @@ Welcome to Panurus documentation. ## Security * [**HTLC Deadlines and Clock Synchronisation**](security/htlc_deadline_clock_assumptions.md): The clock-synchronisation assumption that the HTLC claim/reclaim deadline rests on, and the deadline margin it requires of a deployment. +* [**Signature Observability and Throttling**](security/signature_observability.md): Metrics, the audit trail, and the escalating throttle policy on the signer/verifier surface. * [**Selector Resource Limits**](security/selector_resource_limits.md): How to throttle token selection by supplying a custom `Locker`. ## Command-Line Tools diff --git a/docs/configuration.md b/docs/configuration.md index 55537dbc06..3536c84d36 100644 --- a/docs/configuration.md +++ b/docs/configuration.md @@ -952,4 +952,74 @@ Default values: - The `memory` backend uses in-process semaphores and provides no cross-replica coordination. It is suitable for single-node or development setups. - When using `postgres`, all auditor replicas must share the same PostgreSQL database so that EID locks are globally visible. - Set `heartbeat` to roughly `ttl / 3` to ensure leases are renewed well before expiry. -- `owner` identifies the replica holding each lease and **must be non-empty and unique per replica**: every lease query (acquire, release, renew, and the pre-write `AssertLocksHeld` check) is scoped by it. If several replicas shared one owner value, those predicates would match each other's rows and mutual exclusion would be lost cluster-wide, so an empty or blank resolved owner is rejected at startup rather than tolerated. A typical cause is a templated node configuration with `fsc.id` left unset. No owner is synthesized as a fallback, because an owner that changed on each restart would leave a replica unable to renew or release the leases it still holds. The `memory` backend has no owner and is unaffected. \ No newline at end of file +- `owner` identifies the replica holding each lease and **must be non-empty and unique per replica**: every lease query (acquire, release, renew, and the pre-write `AssertLocksHeld` check) is scoped by it. If several replicas shared one owner value, those predicates would match each other's rows and mutual exclusion would be lost cluster-wide, so an empty or blank resolved owner is rejected at startup rather than tolerated. A typical cause is a templated node configuration with `fsc.id` left unset. No owner is synthesized as a fallback, because an owner that changed on each restart would leave a replica unable to renew or release the leases it still holds. The `memory` backend has no owner and is unaffected. + +--- + +### Optional: token.tms..identity.throttle + +Escalating throttle policy on the signer/verifier surface: per-principal rate limiting plus +automatic escalation on error and invalid-signature ratios. See +[docs/security/signature_observability.md](security/signature_observability.md) for the metrics, +the audit trail, and the enforcement boundary. + +If not specified, the default configuration is: + +```yaml +token: + tms: + : + identity: + throttle: + mode: monitor + rate: 200 + burst: 400 + window: 1m + minSamples: 50 + errorRateThreshold: 0.5 + invalidSignatureRateThreshold: 0.2 + quotaReductionFactor: 0.25 + softDuration: 5m + blockDuration: 1m + deescalateAfter: 5m + idleTTL: 10m +``` + +Default values: + +- mode: monitor +- rate: 200 +- burst: 400 +- window: 1m +- minSamples: 50 +- errorRateThreshold: 0.5 +- invalidSignatureRateThreshold: 0.2 +- quotaReductionFactor: 0.25 +- softDuration: 5m +- blockDuration: 1m +- deescalateAfter: 5m +- idleTTL: 10m + +**Parameter Descriptions:** + +- **mode**: `off` (nothing metered, nothing denied), `monitor` (evaluate and report, never deny) or `enforce` (deny throttled principals) +- **rate**: Metered signature operations per second allowed per principal; a negative value disables the policy like `off` +- **burst**: Token bucket capacity, absorbing short spikes without raising the sustained rate; values below `rate` are raised to `rate` +- **window**: Period over which the error and invalid-signature ratios are evaluated +- **minSamples**: Minimum number of observations in a window before a ratio can escalate a principal +- **errorRateThreshold**: Fraction of failing operations in a window that escalates a principal; a value greater than `1` disables this trigger +- **invalidSignatureRateThreshold**: Fraction of rejected verifications in a window that escalates a principal +- **quotaReductionFactor**: Multiplier applied to `rate` and `burst` while a principal is soft-limited; must be in `(0,1]` +- **softDuration**: Minimum time a principal stays on the reduced quota +- **blockDuration**: How long a blocked principal is refused before being released back to the reduced quota +- **deescalateAfter**: Violation-free period required before a level is restored +- **idleTTL**: How long per-principal state is kept after its last operation + +**Notes:** + +- The default `monitor` mode reports what `enforce` would have denied, so thresholds can be tuned + against production traffic before they bite. +- Out-of-range values (an `invalidSignatureRateThreshold` below 0, a `quotaReductionFactor` outside + `(0,1]`, an unknown `mode`) fail at startup rather than being clamped. +- Denied operations return an error wrapping `token.SignatureThrottled`; callers detect it with + `errors.Is` and back off. diff --git a/docs/security/signature_observability.md b/docs/security/signature_observability.md new file mode 100644 index 0000000000..a3cafd24ef --- /dev/null +++ b/docs/security/signature_observability.md @@ -0,0 +1,248 @@ +# Signature Observability and Throttling + +## Overview + +Every signature the node produces or checks goes through two services: the identity +provider (which resolves *signers*) and the deserializer (which resolves *verifiers*). +Before this feature they were silent — a caller hammering `GetSigner`, or feeding a +stream of forged signatures to `OwnerVerifier`, looked exactly like healthy traffic, and +the only evidence was CPU time. + +Panurus now: + +1. **Instruments** both services. Every operation produces one event — what was + done, for which principal, with what outcome, and how long it took. +2. **Exports** those events as Prometheus metrics and as a privacy-safe audit log. +3. **Escalates** automatically: a principal whose request rate, error ratio, or + invalid-signature ratio crosses a threshold is moved to a reduced quota and, if it + keeps going, blocked for a while. + +Instrumentation is always on and costs a no-op call when nothing is wired to it. The +throttle policy defaults to **monitor** — it evaluates and reports but never denies — +so enabling enforcement is a deliberate decision. + +## Principals + +Every event is attributed to a **principal**: the identity hash, +`driver.Identity.UniqueID()`, of the identity the operation was performed for. + +Raw identity bytes are never used as a metric label, never logged, and never used as a +throttle key. The hash is stable, it is already the signer cache key, and it keeps +identity material (which for X.509 identities includes the certificate) out of logs and +out of a metrics database. + +Operations that cannot be attributed to a single identity — `AreMe` over a batch, for +instance — are reported with an empty principal and are never throttled. Charging a +batch to one of its members would let unrelated callers throttle each other. + +## Where the gate applies + +**Instrumentation is installed everywhere. The gate is consulted at exactly one place: +`token.SignatureService`, the client-facing entry point.** + +This is a deliberate asymmetry. `GetOwnerVerifier` and friends are also called by driver +*validators*, while validating a transaction. Denying a verifier resolution there would +make the validity of a transaction depend on the local call history of whichever node +happened to validate it — two nodes would disagree about the same transaction. So the +validators' deserializers are instrumented (their events feed the metrics and the +policy) but never gated. + +`AreMe` and `IsMe` are not gated either, even at the client boundary: they answer a +question about local state and have no way to express "refused". Returning `false` for an +identity that is in fact ours would be a wrong answer, not a denial. + +`AuditorVerifier` and `GetSigner` are also **not gated**, even though they are +client-facing, for a different reason: the identities they receive come from trusted +fixed sources that are not attacker-controlled. + +- `AuditorVerifier` is called with auditor identities taken from the public parameters + of the token system. That set is tiny and fixed per deployment. Charging every + transaction to one of those buckets would make `DefaultRate` a hard ceiling on + transaction throughput for the node. +- `GetSigner` is called on the hot endorsement path with the node's own long-term signing + identity. All endorsements on that node would share one bucket, so the 200 ops/s + default would be a global endorsement rate limit. + +Both operations are still instrumented downstream (in the deserializer and the identity +provider respectively), so their events feed the metrics and the audit log. Only the +gate is bypassed. + +Callers of `AuditorVerifier` must still be prepared for the error sentinel returned by a +gated downstream: if the signature service ever returns `token.SignatureThrottled` — for +example from a gated verifier inside the deserializer — callers should propagate it +distinctly rather than folding it into a generic "failed verifying signature" error. + +## Metrics + +All metrics are TMS-scoped: the `network`, `channel` and `namespace` labels are added by +the TMS metrics provider, ahead of the labels listed below. + +| Metric | Type | Labels | What it tells you | +|--------|------|--------|-------------------| +| `identity_signature_operations_total` | counter | `op`, `role`, `outcome` | The main series. A rising `outcome="invalid"` on `op="verify"`, or a rising `outcome="throttled"`, is a misbehaving caller. | +| `identity_signature_operation_duration_seconds` | histogram | `op` | Latency per operation. Signature work is CPU-bound, so this is where a resource-exhaustion attempt shows up. | +| `identity_signer_cache_lookups_total` | counter | `result` (`hit`/`miss`) | A collapsing hit ratio means signer material is re-derived on every call. | +| `identity_throttle_escalations_total` | counter | `level`, `reason` | Every level change, including de-escalations back to `normal`. | +| `identity_throttled_principals` | gauge | `level` | How many principals are currently at `soft` / `blocked`. | +| `identity_signer_resolutions_total` | counter | `outcome` (`cache`/`routed`/`fallback`) | How signers are being obtained. | +| `identity_get_signer_duration_seconds` | histogram | `path` | Latency of signer resolution per path. | + +`op` is one of `get_signer`, `register_signer`, `register_identity_descriptor`, `is_me`, +`get_audit_info`, `bind`, `owner_verifier`, `issuer_verifier`, `auditor_verifier`, +`sign`, `verify`, `escalation`. `role` is `owner`, `issuer`, `auditor` or `unknown`. +`outcome` is `ok`, `error`, `invalid` or `throttled`. + +`invalid` and `error` are deliberately separate. A `Verifier` that returns an error has +*rejected a signature*; a `GetSigner` that returns an error hit a missing signer or a +storage failure. The first is a security signal, the second is an operational one. + +Cardinality is bounded by those closed sets. No metric carries a per-identity label, +since the number of identities a deployment sees is unbounded. + +### Suggested alerts + +```promql +# A principal is presenting rejected signatures. +rate(identity_signature_operations_total{op="verify",outcome="invalid"}[5m]) > 1 + +# The policy is actively refusing work. +identity_throttled_principals{level="blocked"} > 0 + +# Enforcement is on and someone is hitting it. +rate(identity_signature_operations_total{outcome="throttled"}[5m]) > 0 +``` + +## The audit log + +Alongside the metrics, each event is written as a single structured line to the +`panurus.driver..signature` logger: + +``` +sig-audit op=get_signer principal=abcd1234 role=owner outcome=ok path=cache cache=hit duration_ms=1.500 +sig-audit op=verify principal=abcd1234 role=owner outcome=invalid duration_ms=0.412 err=[signature mismatch] +sig-audit op=escalation principal=abcd1234 role=unknown outcome=ok level=blocked reason=invalid_signature_rate +``` + +Log level follows the outcome, so a deployment can keep the interesting lines without +the volume of the routine ones: + +| Outcome | Level | +|---------|-------| +| `ok` | debug | +| `error`, `invalid`, `throttled` | warn | +| `escalation` (policy state) | info | + +Fields that do not apply are omitted; an unattributed operation is written as +`principal=none`. As with the metrics, the `principal` field is an identity hash — the +audit log never contains identity bytes. + +## The escalation policy + +The policy keeps, per principal, a token bucket and a sliding window (one minute by +default, in ten-second steps) of operation counts. A principal moves up a level when: + +- it exhausts its token bucket (`reason=rate`), or +- the fraction of its operations that failed crosses `errorRateThreshold` + (`reason=error_rate`), or +- the fraction of its verifications that were rejected crosses + `invalidSignatureRateThreshold` (`reason=invalid_signature_rate`). + +Ratios are only evaluated once the window holds at least `minSamples` observations: one +failure out of three calls is not an attack. + +The levels are: + +| Level | Effect | +|-------|--------| +| `normal` | Full quota. | +| `soft` | Rate and burst multiplied by `quotaReductionFactor`, for at least `softDuration`. A soft-limited principal is slowed, never stopped: the reduced bucket always keeps room for one token. | +| `blocked` | Metered operations refused for `blockDuration`, then released back to `soft` (`reason=block_expired`). | + +A principal that goes `deescalateAfter` without a violation is restored one level at a +time (`reason=quiet_period`). Each transition resets the window, so the counters that +caused an escalation cannot immediately trigger the next one. Per-principal state is +dropped after `idleTTL` of inactivity — except for principals above `normal`, whose +state *is* the record that they are throttled. + +## Handling a denial + +A denied operation returns an error wrapping the `token.SignatureThrottled` sentinel. +Callers should treat it as "back off", distinct from "unknown identity" or "invalid +signature": + +```go +signer, err := signatureService.GetSigner(ctx, id) +if errors.Is(err, token.SignatureThrottled) { + // back off and retry later, shed the request, or surface a 429-style response +} +``` + +## Configuration + +The policy is read per TMS from `token.tms..identity.throttle`. The whole section +is optional; a missing section means the defaults below. + +```yaml +token: + tms: + : + identity: + throttle: + mode: monitor + rate: 200 + burst: 400 + window: 1m + minSamples: 50 + errorRateThreshold: 0.5 + invalidSignatureRateThreshold: 0.2 + quotaReductionFactor: 0.25 + softDuration: 5m + blockDuration: 1m + deescalateAfter: 5m + idleTTL: 10m +``` + +| Field | Default | Description | +|-------|---------|-------------| +| `mode` | `monitor` | `off` — nothing metered, nothing denied. `monitor` — evaluate and report, never deny. `enforce` — deny throttled principals. | +| `rate` | `200` | Metered signature operations per second per principal. A negative value disables the policy, like `off`. | +| `burst` | `400` | Bucket capacity, absorbing short spikes without raising the sustained rate. Values below `rate` are raised to `rate`. | +| `window` | `1m` | Evaluation period for the ratio thresholds. | +| `minSamples` | `50` | Minimum observations in a window before a ratio can escalate a principal. | +| `errorRateThreshold` | `0.5` | Failing-operation fraction that escalates. A value greater than `1` disables this trigger. | +| `invalidSignatureRateThreshold` | `0.2` | Rejected-verification fraction that escalates. Stricter than the error threshold: a healthy caller does not present bad signatures. | +| `quotaReductionFactor` | `0.25` | Multiplier applied to `rate` and `burst` at level `soft`. Must be in `(0,1]`. | +| `softDuration` | `5m` | Minimum time on a reduced quota. | +| `blockDuration` | `1m` | How long a blocked principal is refused before release back to `soft`. | +| `deescalateAfter` | `5m` | Violation-free period required to restore a level. | +| `idleTTL` | `10m` | How long per-principal state is kept after its last operation. | + +Out-of-range values are rejected at startup rather than clamped: a configuration asking +for a `quotaReductionFactor` of `3` has a mistake in it, and silently treating it as `1` +would leave the operator believing a policy is in force that is not. + +### Rolling out enforcement + +1. Deploy with the default `monitor` mode. +2. Watch `identity_throttle_escalations_total` and the audit log's `op=escalation` + lines. In monitor mode these are exactly the denials that `enforce` would have made. +3. Adjust `rate`, `burst` and the two thresholds until only traffic you would want to + refuse escalates. +4. Switch `mode` to `enforce`. + +## Implementation notes + +For contributors: + +- `token/services/identity/sigobserve` — the event vocabulary (`Event`, `Op`, `Outcome`, + `Observer`, `Gate`), the `Timer` that times an operation without allocating, the + `InstrumentSigner`/`InstrumentVerifier` decorators, and the audit logger. It depends on + nothing but `token/driver`, which is what lets `token` import it without a cycle. +- `token/services/identity/throttle` — the escalation policy. It is both an `Observer` + (it watches outcomes) and a `Gate` (it decides). +- `token/services/ratelimit` — the per-key token buckets the policy meters with. +- `token/services/identity/sigpolicy` — assembles metrics + audit log + policy into one + `Stack`, so the wiring lives in one place instead of in every driver. +- `token/services/identity/metrics.go` — the Prometheus sink. Every metric must declare + `network`, `channel`, `namespace` as its leading labels; the TMS provider prepends + those values, and a metric that omits them makes Prometheus reject the series. diff --git a/token/core/common/deserializer.go b/token/core/common/deserializer.go index 86a1beff57..43afc9f9b3 100644 --- a/token/core/common/deserializer.go +++ b/token/core/common/deserializer.go @@ -10,6 +10,7 @@ import ( "context" "github.com/LFDT-Panurus/panurus/token/driver" + "github.com/LFDT-Panurus/panurus/token/services/identity/sigobserve" ) // Deserializer deserializes verifiers associated with issuers, owners, and auditors @@ -19,6 +20,10 @@ type Deserializer struct { issuerDeserializer driver.VerifierDeserializer auditMatcherProvider driver.AuditMatcherProvider recipientExtractor driver.RecipientExtractor + + // observer receives one event per verifier resolution, and one per Verify performed with a + // resolved verifier. It defaults to a no-op, so an unwired deserializer costs nothing. + observer sigobserve.Observer } // NewDeserializer returns a new Deserializer for the passed arguments. @@ -35,22 +40,47 @@ func NewDeserializer( issuerDeserializer: issuerDeserializer, auditMatcherProvider: auditMatcherProvider, recipientExtractor: recipientExtractor, + observer: sigobserve.Nop, + } +} + +// SetObserver installs the observer that verifier resolutions, and the verifications performed +// with the resolved verifiers, are reported to. Passing nil restores the no-op observer. +// +// It is a setter rather than a constructor parameter because a deserializer is built by every +// driver and by the validators, and only the ones a node builds for its own client-facing +// services have an observer to give. +func (d *Deserializer) SetObserver(o sigobserve.Observer) { + if o == nil { + o = sigobserve.Nop } + d.observer = o } // GetOwnerVerifier returns the verifier associated to the passed owner identity. func (d *Deserializer) GetOwnerVerifier(ctx context.Context, id driver.Identity) (driver.Verifier, error) { - return d.ownerDeserializer.DeserializeVerifier(ctx, id) + return d.getVerifier(ctx, d.ownerDeserializer, id, sigobserve.OpOwnerVerifier, sigobserve.RoleOwner) } // GetIssuerVerifier returns the verifier associated to the passed issuer identity. func (d *Deserializer) GetIssuerVerifier(ctx context.Context, id driver.Identity) (driver.Verifier, error) { - return d.issuerDeserializer.DeserializeVerifier(ctx, id) + return d.getVerifier(ctx, d.issuerDeserializer, id, sigobserve.OpIssuerVerifier, sigobserve.RoleIssuer) } // GetAuditorVerifier returns the verifier associated to the passed auditor identity. func (d *Deserializer) GetAuditorVerifier(ctx context.Context, id driver.Identity) (driver.Verifier, error) { - return d.auditorDeserializer.DeserializeVerifier(ctx, id) + return d.getVerifier(ctx, d.auditorDeserializer, id, sigobserve.OpAuditorVerifier, sigobserve.RoleAuditor) +} + +// getVerifier resolves a verifier through vd, reports the resolution as op, and wraps the result +// so that the verifications it performs are reported too. +func (d *Deserializer) getVerifier(ctx context.Context, vd driver.VerifierDeserializer, id driver.Identity, op sigobserve.Op, role sigobserve.Role) (driver.Verifier, error) { + principal := id.UniqueID() + t := sigobserve.Start(d.observer, op, principal, role) + verifier, err := vd.DeserializeVerifier(ctx, id) + t.Done(ctx, err) + + return sigobserve.InstrumentVerifier(verifier, d.observer, principal, role), err } // Recipients returns the recipient identities extracted from the passed identity. diff --git a/token/core/common/deserializer_observe_test.go b/token/core/common/deserializer_observe_test.go new file mode 100644 index 0000000000..c4bf2a6dd3 --- /dev/null +++ b/token/core/common/deserializer_observe_test.go @@ -0,0 +1,174 @@ +/* +Copyright IBM Corp. All Rights Reserved. + +SPDX-License-Identifier: Apache-2.0 +*/ + +package common + +import ( + "context" + "sync" + "testing" + + "github.com/LFDT-Panurus/panurus/token/driver" + dmock "github.com/LFDT-Panurus/panurus/token/driver/mock" + "github.com/LFDT-Panurus/panurus/token/services/identity/sigobserve" + "github.com/hyperledger-labs/fabric-smart-client/pkg/utils/errors" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +// sigRecorder collects the events the deserializer reports. +type sigRecorder struct { + mu sync.Mutex + events []sigobserve.Event +} + +func (r *sigRecorder) Observe(_ context.Context, e sigobserve.Event) { + r.mu.Lock() + defer r.mu.Unlock() + r.events = append(r.events, e) +} + +func (r *sigRecorder) all() []sigobserve.Event { + r.mu.Lock() + defer r.mu.Unlock() + + return append([]sigobserve.Event(nil), r.events...) +} + +func (r *sigRecorder) one(t *testing.T) sigobserve.Event { + t.Helper() + events := r.all() + require.Len(t, events, 1) + + return events[0] +} + +// observedDeserializer is a Deserializer wired to a recorder, with its per-role deserializers +// exposed so a test can drive one of them. +type observedDeserializer struct { + des *Deserializer + owner *dmock.VerifierDeserializer + issuer *dmock.VerifierDeserializer + auditor *dmock.VerifierDeserializer + events *sigRecorder +} + +func newObservedDeserializer() *observedDeserializer { + o := &observedDeserializer{ + owner: &dmock.VerifierDeserializer{}, + issuer: &dmock.VerifierDeserializer{}, + auditor: &dmock.VerifierDeserializer{}, + events: &sigRecorder{}, + } + o.des = NewDeserializer(o.auditor, o.owner, o.issuer, &dmock.AuditMatcherProvider{}, &dmock.RecipientExtractor{}) + o.des.SetObserver(o.events) + + return o +} + +func TestDeserializerObservesVerifierResolution(t *testing.T) { + id := driver.Identity("an_identity") + tests := []struct { + name string + resolve func(o *observedDeserializer) (driver.Verifier, error) + mockOf func(o *observedDeserializer) *dmock.VerifierDeserializer + op sigobserve.Op + role sigobserve.Role + }{ + { + name: "owner", + resolve: func(o *observedDeserializer) (driver.Verifier, error) { return o.des.GetOwnerVerifier(t.Context(), id) }, + mockOf: func(o *observedDeserializer) *dmock.VerifierDeserializer { return o.owner }, + op: sigobserve.OpOwnerVerifier, + role: sigobserve.RoleOwner, + }, + { + name: "issuer", + resolve: func(o *observedDeserializer) (driver.Verifier, error) { + return o.des.GetIssuerVerifier(t.Context(), id) + }, + mockOf: func(o *observedDeserializer) *dmock.VerifierDeserializer { return o.issuer }, + op: sigobserve.OpIssuerVerifier, + role: sigobserve.RoleIssuer, + }, + { + name: "auditor", + resolve: func(o *observedDeserializer) (driver.Verifier, error) { + return o.des.GetAuditorVerifier(t.Context(), id) + }, + mockOf: func(o *observedDeserializer) *dmock.VerifierDeserializer { return o.auditor }, + op: sigobserve.OpAuditorVerifier, + role: sigobserve.RoleAuditor, + }, + } + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + o := newObservedDeserializer() + test.mockOf(o).DeserializeVerifierReturns(&dmock.Verifier{}, nil) + + _, err := test.resolve(o) + require.NoError(t, err) + + event := o.events.one(t) + assert.Equal(t, test.op, event.Op) + assert.Equal(t, test.role, event.Role, "the role is what makes an owner's traffic separable from an issuer's") + assert.Equal(t, id.UniqueID(), event.Principal) + assert.Equal(t, sigobserve.OutcomeOK, event.Outcome) + }) + } +} + +func TestDeserializerObservesResolutionFailure(t *testing.T) { + o := newObservedDeserializer() + o.owner.DeserializeVerifierReturns(nil, errors.New("unknown identity")) + + verifier, err := o.des.GetOwnerVerifier(t.Context(), driver.Identity("an_identity")) + require.Error(t, err) + assert.Nil(t, verifier, "a failed resolution must not hand back an instrumented nil") + + event := o.events.one(t) + assert.Equal(t, sigobserve.OutcomeError, event.Outcome) + assert.ErrorContains(t, event.Err, "unknown identity") +} + +// TestDeserializerObservesVerificationsWithTheResolvedVerifier covers the point of wrapping the +// verifier: a rejected signature is what an attack looks like, and it happens after the +// resolution the deserializer could otherwise report on its own. +func TestDeserializerObservesVerificationsWithTheResolvedVerifier(t *testing.T) { + o := newObservedDeserializer() + verifier := &dmock.Verifier{} + verifier.VerifyReturns(errors.New("signature mismatch")) + o.owner.DeserializeVerifierReturns(verifier, nil) + + id := driver.Identity("an_identity") + resolved, err := o.des.GetOwnerVerifier(t.Context(), id) + require.NoError(t, err) + require.Error(t, resolved.Verify([]byte("message"), []byte("sigma"))) + + events := o.events.all() + require.Len(t, events, 2) + verifyEvent := events[1] + assert.Equal(t, sigobserve.OpVerify, verifyEvent.Op) + assert.Equal(t, sigobserve.RoleOwner, verifyEvent.Role) + assert.Equal(t, id.UniqueID(), verifyEvent.Principal) + assert.Equal(t, sigobserve.OutcomeInvalid, verifyEvent.Outcome, + "a rejected signature is not a service failure and must be counted apart from one") +} + +// TestDeserializerWithoutObserverIsTransparent pins the default a validator gets: no events, and +// the verifier the underlying deserializer produced, unwrapped. +func TestDeserializerWithoutObserverIsTransparent(t *testing.T) { + o := newObservedDeserializer() + expected := &dmock.Verifier{} + o.owner.DeserializeVerifierReturns(expected, nil) + + o.des.SetObserver(nil) + + resolved, err := o.des.GetOwnerVerifier(t.Context(), driver.Identity("an_identity")) + require.NoError(t, err) + assert.Same(t, expected, resolved) + assert.Empty(t, o.events.all()) +} diff --git a/token/core/common/tms.go b/token/core/common/tms.go index ba4a6cec32..4829393497 100644 --- a/token/core/common/tms.go +++ b/token/core/common/tms.go @@ -8,9 +8,24 @@ package common import ( "github.com/LFDT-Panurus/panurus/token/driver" + "github.com/LFDT-Panurus/panurus/token/services/identity/sigobserve" "github.com/LFDT-Panurus/panurus/token/services/logging" ) +// SignatureInstrumentation bundles the observability and policy a driver installs on a token +// service: the observer its signature operations are reported to, and the gate that may deny +// them. It is an interface so that this package does not depend on the policy implementation; +// sigpolicy.Stack is what a driver actually passes. +type SignatureInstrumentation interface { + // Observer returns the observer signature operations are reported to. + Observer() sigobserve.Observer + // Gate returns the gate consulted before a client-facing signature operation, or nil when + // no policy is active. + Gate() sigobserve.Gate + // Stop releases the resources held by the instrumentation. + Stop() +} + // ValidatorFactory is a function that returns a driver.Validator instance. type ValidatorFactory = func() (driver.Validator, error) @@ -36,6 +51,8 @@ type Service[T driver.PublicParameters] struct { tokensUpgradeService driver.TokensUpgradeService authorization driver.Authorization validator driver.Validator + + signatureInstrumentation SignatureInstrumentation } // NewTokenService returns a new token service instance for the passed arguments. @@ -75,6 +92,34 @@ func NewTokenService[T driver.PublicParameters]( return s, nil } +// SetSignatureInstrumentation installs the signature observability and policy bundle. It is a +// setter rather than a constructor parameter because the bundle is assembled together with the +// wallet service, before this service exists, and because a driver that installs none must keep +// working unchanged. +func (s *Service[T]) SetSignatureInstrumentation(si SignatureInstrumentation) { + s.signatureInstrumentation = si +} + +// SignatureObserver returns the observer the client-facing signature service reports denials to, +// or a no-op observer when no instrumentation is installed. +func (s *Service[T]) SignatureObserver() sigobserve.Observer { + if s.signatureInstrumentation == nil { + return sigobserve.Nop + } + + return s.signatureInstrumentation.Observer() +} + +// SignatureGate returns the gate the client-facing signature service consults, or nil when no +// policy is active. +func (s *Service[T]) SignatureGate() sigobserve.Gate { + if s.signatureInstrumentation == nil { + return nil + } + + return s.signatureInstrumentation.Gate() +} + // IdentityProvider returns the identity provider associated with the service. func (s *Service[T]) IdentityProvider() driver.IdentityProvider { return s.identityProvider @@ -142,6 +187,10 @@ func (s *Service[T]) Validator() (driver.Validator, error) { // Done releases all the resources allocated by this service. func (s *Service[T]) Done() error { + if s.signatureInstrumentation != nil { + s.signatureInstrumentation.Stop() + } + // call done on all the services that support it if s.walletService != nil { return s.walletService.Done() diff --git a/token/core/fabtoken/v1/driver/driver.go b/token/core/fabtoken/v1/driver/driver.go index 4ef77eb411..4eefc5b9ff 100644 --- a/token/core/fabtoken/v1/driver/driver.go +++ b/token/core/fabtoken/v1/driver/driver.go @@ -132,7 +132,7 @@ func (d *Driver) NewTokenService(tmsID driver.TMSID, publicParams []byte) (drive networkLocalMembership := n.LocalMembership() qe := vault.QueryEngine() metricsProvider := metrics.NewTMSProvider(tmsConfig.ID(), d.metricsProvider) - ws, err := d.newWalletService( + ws, sigStack, err := d.newWalletService( tmsConfig, d.endpointService, d.storageProvider, @@ -147,6 +147,12 @@ func (d *Driver) NewTokenService(tmsID driver.TMSID, publicParams []byte) (drive if err != nil { return nil, errors.Wrapf(err, "failed to initiliaze wallet service for [%s:%s]", tmsID.Network, tmsID.Namespace) } + transferred := false + defer func() { + if !transferred { + sigStack.Stop() + } + }() deserializer := ws.Deserializer ip := ws.IdentityProvider @@ -191,6 +197,10 @@ func (d *Driver) NewTokenService(tmsID driver.TMSID, publicParams []byte) (drive if err != nil { return nil, errors.WithMessagef(err, "failed to create token service") } + // The stack gates this service's client-facing signature service and is released when the + // service is done with. + service.SetSignatureInstrumentation(sigStack) + transferred = true return service, nil } diff --git a/token/core/fabtoken/v1/driver/ws.go b/token/core/fabtoken/v1/driver/ws.go index 152190d353..7ae50758ba 100644 --- a/token/core/fabtoken/v1/driver/ws.go +++ b/token/core/fabtoken/v1/driver/ws.go @@ -16,6 +16,7 @@ import ( "github.com/LFDT-Panurus/panurus/token/services/identity/deserializer" "github.com/LFDT-Panurus/panurus/token/services/identity/membership" "github.com/LFDT-Panurus/panurus/token/services/identity/role" + "github.com/LFDT-Panurus/panurus/token/services/identity/sigpolicy" "github.com/LFDT-Panurus/panurus/token/services/identity/wallet" "github.com/LFDT-Panurus/panurus/token/services/identity/x509" "github.com/LFDT-Panurus/panurus/token/services/logging" @@ -27,8 +28,10 @@ type BaseWalletServiceFactory struct { PublicParametersDeserializer } -// newWalletService returns a new wallet service for the passed configuration and parameters. -// newWalletService returns a new wallet service for the passed configuration and parameters. +// newWalletService returns a new wallet service for the passed configuration and parameters, +// together with the signature observability stack its identity provider and deserializer report +// to. The caller owns the stack: it must install it on the token service (so that the +// client-facing signature service is gated by it and it is stopped with the service) or stop it. func (d BaseWalletServiceFactory) newWalletService( tmsConfig core.Config, binder identity.NetworkBinderService, @@ -40,25 +43,30 @@ func (d BaseWalletServiceFactory) newWalletService( pp driver.PublicParameters, ignoreRemote bool, metricsProvider metrics.Provider, -) (*wallet.Service, error) { +) (*wallet.Service, *sigpolicy.Stack, error) { tmsID := tmsConfig.ID() deserializerManager := deserializer.NewTypedSignerDeserializerMultiplex() identityDB, err := storageProvider.IdentityStore(tmsID) if err != nil { - return nil, errors.Wrapf(err, "failed to open identity db for tms [%s]", tmsID) + return nil, nil, errors.Wrapf(err, "failed to open identity db for tms [%s]", tmsID) } baseKeyStore, err := storageProvider.Keystore(tmsID) if err != nil { - return nil, errors.Wrapf(err, "failed to open keystore for tms [%s]", tmsID) + return nil, nil, errors.Wrapf(err, "failed to open keystore for tms [%s]", tmsID) } identityMetrics := identity.NewMetrics(metricsProvider) + sigStack, err := sigpolicy.New(logger.Named("signature"), tmsConfig, identityMetrics) + if err != nil { + return nil, nil, errors.WithMessagef(err, "failed to create signature policy for tms [%s]", tmsID) + } signerRouter := identity.NewSignerRouter(identityMetrics) identityProvider := identity.NewProvider(logger.Named("identity"), identityDB, deserializerManager, binder, NewEIDRHDeserializer(), identityMetrics) identityProvider.SetSignerRouter(signerRouter) + identityProvider.SetObserver(sigStack.Observer()) identityConfig, err := config.NewIdentityConfig(tmsConfig) if err != nil { - return nil, errors.WithMessagef(err, "failed to create identity config") + return nil, nil, errors.WithMessagef(err, "failed to create identity config") } // Prepare roles @@ -76,33 +84,34 @@ func (d BaseWalletServiceFactory) newWalletService( roleFactory.SetSignerRouter(signerRouter) newRole, err := roleFactory.NewRole(identity.OwnerRole, false, nil, x509.NewKeyManagerProvider(identityConfig, keyStore, ignoreRemote)) if err != nil { - return nil, errors.WithMessagef(err, "failed to create owner role") + return nil, nil, errors.WithMessagef(err, "failed to create owner role") } roles := role.NewRoles() roles.Register(identity.OwnerRole, newRole) newRole, err = roleFactory.NewRole(identity.IssuerRole, false, pp.Issuers(), x509.NewKeyManagerProvider(identityConfig, keyStore, ignoreRemote)) if err != nil { - return nil, errors.WithMessagef(err, "failed to create issuer role") + return nil, nil, errors.WithMessagef(err, "failed to create issuer role") } roles.Register(identity.IssuerRole, newRole) newRole, err = roleFactory.NewRole(identity.AuditorRole, false, pp.Auditors(), x509.NewKeyManagerProvider(identityConfig, keyStore, ignoreRemote)) if err != nil { - return nil, errors.WithMessagef(err, "failed to create auditor role") + return nil, nil, errors.WithMessagef(err, "failed to create auditor role") } roles.Register(identity.AuditorRole, newRole) newRole, err = roleFactory.NewRole(identity.CertifierRole, false, nil, x509.NewKeyManagerProvider(identityConfig, keyStore, ignoreRemote)) if err != nil { - return nil, errors.WithMessagef(err, "failed to create certifier role") + return nil, nil, errors.WithMessagef(err, "failed to create certifier role") } roles.Register(identity.CertifierRole, newRole) // Instantiate the wallet service walletDB, err := storageProvider.WalletStore(tmsID) if err != nil { - return nil, errors.Wrapf(err, "failed to get identity storage provider") + return nil, nil, errors.Wrapf(err, "failed to get identity storage provider") } signerRouter.SetConfIDResolver(walletDB) deserializer := NewDeserializer() + deserializer.SetObserver(sigStack.Observer()) ws := wallet.NewService( logger, identityProvider, @@ -110,7 +119,7 @@ func (d BaseWalletServiceFactory) newWalletService( wallet.Convert(roles.Registries(logger, walletDB, role.NewDefaultFactory(logger, identityProvider, qe, identityConfig, deserializer, metricsProvider))), ) - return ws, nil + return ws, sigStack, nil } // WalletServiceFactory is a factory for fabtoken wallet services. @@ -133,7 +142,7 @@ func (d *WalletServiceFactory) NewWalletService(tmsConfig driver.Configuration, tmsID := tmsConfig.ID() logger := logging.DriverLogger("panurus.driver.fabtoken", tmsID.Network, tmsID.Channel, tmsID.Namespace) - return d.newWalletService( + ws, sigStack, err := d.newWalletService( tmsConfig, &membership.NoBinder{}, d.storageProvider, @@ -145,4 +154,13 @@ func (d *WalletServiceFactory) NewWalletService(tmsConfig driver.Configuration, true, &disabled.Provider{}, ) + if err != nil { + return nil, err + } + // This factory builds a standalone wallet service with no client-facing signature service to + // gate, so the policy's background eviction has nothing to serve. Instrumentation keeps + // working: stopping the stack only releases its goroutine. + sigStack.Stop() + + return ws, nil } diff --git a/token/core/zkatdlog/nogh/v1/driver/driver.go b/token/core/zkatdlog/nogh/v1/driver/driver.go index 025383a0a9..5288906df0 100644 --- a/token/core/zkatdlog/nogh/v1/driver/driver.go +++ b/token/core/zkatdlog/nogh/v1/driver/driver.go @@ -134,7 +134,7 @@ func (d *Driver) NewTokenService(tmsID driver.TMSID, publicParams []byte) (drive metricsProvider := metrics.NewTMSProvider(tmsConfig.ID(), d.metricsProvider) qe := vault.QueryEngine() - ws, err := d.NewWalletService( + ws, sigStack, err := d.newWalletService( tmsConfig, d.endpointService, d.storageProvider, @@ -149,6 +149,12 @@ func (d *Driver) NewTokenService(tmsID driver.TMSID, publicParams []byte) (drive if err != nil { return nil, errors.Wrapf(err, "failed to initiliaze wallet service for [%s:%s]", tmsID.Network, tmsID.Namespace) } + transferred := false + defer func() { + if !transferred { + sigStack.Stop() + } + }() deserializer := ws.Deserializer ip := ws.IdentityProvider @@ -213,6 +219,10 @@ func (d *Driver) NewTokenService(tmsID driver.TMSID, publicParams []byte) (drive if err != nil { return nil, errors.WithMessagef(err, "failed to create token service") } + // The stack gates this service's client-facing signature service and is released when the + // service is done with. + service.SetSignatureInstrumentation(sigStack) + transferred = true return service, err } diff --git a/token/core/zkatdlog/nogh/v1/driver/ws.go b/token/core/zkatdlog/nogh/v1/driver/ws.go index 732c92782e..0ae5cd2149 100644 --- a/token/core/zkatdlog/nogh/v1/driver/ws.go +++ b/token/core/zkatdlog/nogh/v1/driver/ws.go @@ -18,6 +18,7 @@ import ( "github.com/LFDT-Panurus/panurus/token/services/identity/idemixnym" "github.com/LFDT-Panurus/panurus/token/services/identity/membership" "github.com/LFDT-Panurus/panurus/token/services/identity/role" + "github.com/LFDT-Panurus/panurus/token/services/identity/sigpolicy" "github.com/LFDT-Panurus/panurus/token/services/identity/wallet" "github.com/LFDT-Panurus/panurus/token/services/identity/x509" "github.com/LFDT-Panurus/panurus/token/services/logging" @@ -31,6 +32,10 @@ type BaseWalletServiceFactory struct { } // NewWalletService returns a new zkatdlog wallet service. +// +// It is a convenience wrapper over newWalletService for callers that have no client-facing +// signature service to gate: the signature policy stack is stopped before returning, which +// releases its background goroutine while leaving instrumentation in place. func (d *BaseWalletServiceFactory) NewWalletService( tmsConfig core.Config, binder identity.NetworkBinderService, @@ -43,28 +48,69 @@ func (d *BaseWalletServiceFactory) NewWalletService( ignoreRemote bool, metricsProvider metrics.Provider, ) (*wallet.Service, error) { + ws, sigStack, err := d.newWalletService( + tmsConfig, + binder, + storageProvider, + qe, + logger, + fscIdentity, + networkDefaultIdentity, + publicParams, + ignoreRemote, + metricsProvider, + ) + if err != nil { + return nil, err + } + sigStack.Stop() + + return ws, nil +} + +// newWalletService returns a new zkatdlog wallet service together with the signature +// observability stack its identity provider and deserializer report to. The caller owns the +// stack: it must install it on the token service, so that the client-facing signature service is +// gated by it and it is released with the service, or stop it. +func (d *BaseWalletServiceFactory) newWalletService( + tmsConfig core.Config, + binder identity.NetworkBinderService, + storageProvider identity.StorageProvider, + qe driver.QueryEngine, + logger logging.Logger, + fscIdentity view.Identity, + networkDefaultIdentity view.Identity, + publicParams driver.PublicParameters, + ignoreRemote bool, + metricsProvider metrics.Provider, +) (*wallet.Service, *sigpolicy.Stack, error) { pp, ok := publicParams.(*v1.PublicParams) if !ok { - return nil, errors.Errorf("invalid public parameters type [%T]", publicParams) + return nil, nil, errors.Errorf("invalid public parameters type [%T]", publicParams) } roles := role.NewRoles() deserializerManager := deserializer.NewTypedSignerDeserializerMultiplex() tmsID := tmsConfig.ID() identityDB, err := storageProvider.IdentityStore(tmsID) if err != nil { - return nil, errors.Wrapf(err, "failed to open identity db for tms [%s]", tmsID) + return nil, nil, errors.Wrapf(err, "failed to open identity db for tms [%s]", tmsID) } baseKeyStore, err := storageProvider.Keystore(tmsID) if err != nil { - return nil, errors.Wrapf(err, "failed to open keystore for tms [%s]", tmsID) + return nil, nil, errors.Wrapf(err, "failed to open keystore for tms [%s]", tmsID) } identityMetrics := identity.NewMetrics(metricsProvider) + sigStack, err := sigpolicy.New(logger.Named("signature"), tmsConfig, identityMetrics) + if err != nil { + return nil, nil, errors.WithMessagef(err, "failed to create signature policy for tms [%s]", tmsID) + } signerRouter := identity.NewSignerRouter(identityMetrics) identityProvider := identity.NewProvider(logger.Named("identity"), identityDB, deserializerManager, binder, NewEIDRHDeserializer(), identityMetrics) identityProvider.SetSignerRouter(signerRouter) + identityProvider.SetObserver(sigStack.Observer()) identityConfig, err := config.NewIdentityConfig(tmsConfig) if err != nil { - return nil, errors.WithMessagef(err, "failed to create identity config") + return nil, nil, errors.WithMessagef(err, "failed to create identity config") } // Prepare roles @@ -85,7 +131,7 @@ func (d *BaseWalletServiceFactory) NewWalletService( for _, key := range pp.IdemixIssuerPublicKeys { keyStore, err := msp2.NewKeyStore(key.Curve, baseKeyStore) if err != nil { - return nil, errors.Wrapf(err, "failed to instantiate bccsp key store") + return nil, nil, errors.Wrapf(err, "failed to instantiate bccsp key store") } kmp := idemixnym.NewKeyManagerProvider( key.PublicKey, @@ -104,42 +150,45 @@ func (d *BaseWalletServiceFactory) NewWalletService( newRole, err := roleFactory.NewRole(identity.OwnerRole, true, nil, kmps...) if err != nil { - return nil, errors.WithMessagef(err, "failed to create owner role") + return nil, nil, errors.WithMessagef(err, "failed to create owner role") } roles.Register(identity.OwnerRole, newRole) newRole, err = roleFactory.NewRole(identity.IssuerRole, false, pp.Issuers(), x509.NewKeyManagerProvider(identityConfig, keyStore, ignoreRemote)) if err != nil { - return nil, errors.WithMessagef(err, "failed to create issuer role") + return nil, nil, errors.WithMessagef(err, "failed to create issuer role") } roles.Register(identity.IssuerRole, newRole) newRole, err = roleFactory.NewRole(identity.AuditorRole, false, pp.Auditors(), x509.NewKeyManagerProvider(identityConfig, keyStore, ignoreRemote)) if err != nil { - return nil, errors.WithMessagef(err, "failed to create auditor role") + return nil, nil, errors.WithMessagef(err, "failed to create auditor role") } roles.Register(identity.AuditorRole, newRole) newRole, err = roleFactory.NewRole(identity.CertifierRole, false, nil, x509.NewKeyManagerProvider(identityConfig, keyStore, ignoreRemote)) if err != nil { - return nil, errors.WithMessagef(err, "failed to create certifier role") + return nil, nil, errors.WithMessagef(err, "failed to create certifier role") } roles.Register(identity.CertifierRole, newRole) // wallet service walletDB, err := storageProvider.WalletStore(tmsID) if err != nil { - return nil, errors.Wrapf(err, "failed to get identity storage provider") + return nil, nil, errors.Wrapf(err, "failed to get identity storage provider") } signerRouter.SetConfIDResolver(walletDB) deserializer, err := NewDeserializer(pp) if err != nil { - return nil, errors.Wrapf(err, "failed to instantiate the deserializer") + return nil, nil, errors.Wrapf(err, "failed to instantiate the deserializer") } + deserializer.SetObserver(sigStack.Observer()) - return wallet.NewService( + ws := wallet.NewService( logger, identityProvider, deserializer, wallet.Convert(roles.Registries(logger, walletDB, role.NewDefaultFactory(logger, identityProvider, qe, identityConfig, deserializer, metricsProvider))), - ), nil + ) + + return ws, sigStack, nil } // WalletServiceFactory is a factory for creating zkatdlog wallet services. diff --git a/token/services/identity/metrics.go b/token/services/identity/metrics.go index c29fe1df21..37724f8198 100644 --- a/token/services/identity/metrics.go +++ b/token/services/identity/metrics.go @@ -7,7 +7,10 @@ SPDX-License-Identifier: Apache-2.0 package identity import ( + "context" + "github.com/LFDT-Panurus/panurus/token/core/common/metrics" + "github.com/LFDT-Panurus/panurus/token/services/identity/sigobserve" "github.com/hyperledger-labs/fabric-smart-client/platform/view/services/metrics/disabled" ) @@ -33,6 +36,33 @@ type Metrics struct { // cryptographic check that would otherwise catch a mismatched KeyManager, a non-zero // count is worth investigating as a potential conf_id routing bug. NoProbeErrors metrics.Counter + + // SignatureOps counts Signer/Verifier service operations by operation, role and outcome. + // It is the counter an alert is written against: a rising "invalid" outcome on verify, or + // a rising "throttled" outcome, is the signal that a principal is misbehaving. + // + // Its cardinality is bounded by the closed sets of operations, roles and outcomes declared + // in the sigobserve package; no per-identity label is ever attached, since the number of + // identities a deployment sees is unbounded. + SignatureOps metrics.Counter + + // SignatureOpDuration is a histogram of Signer/Verifier operation wall-clock time in + // seconds, labeled by operation only: the outcome is already carried by SignatureOps, and + // crossing it with duration buckets would multiply the series for little insight. + SignatureOpDuration metrics.Histogram + + // SignerCacheLookups counts signer-cache consultations by result ("hit" or "miss"). A + // collapsing hit ratio means signer material is being re-derived on every call, which is + // both a latency and a CPU-exhaustion concern. + SignerCacheLookups metrics.Counter + + // ThrottleEscalations counts throttle level changes by the level entered and the reason. + // De-escalations appear here too, with the level they returned to. + ThrottleEscalations metrics.Counter + + // ThrottledPrincipals reports how many principals are currently held at each throttle + // level above normal. + ThrottledPrincipals metrics.Gauge } func newMetrics(p metrics.Provider) *Metrics { @@ -64,6 +94,34 @@ func newMetrics(p metrics.Provider) *Metrics { Help: "Total number of errors from the SignerRouter's probe-free signer deserialization path", LabelNames: []string{"network", "channel", "namespace"}, }), + SignatureOps: p.NewCounter(metrics.CounterOpts{ + Name: "identity_signature_operations_total", + Help: "Total number of signer/verifier service operations by operation, role and outcome", + LabelNames: []string{"network", "channel", "namespace", "op", "role", "outcome"}, + }), + SignatureOpDuration: p.NewHistogram(metrics.HistogramOpts{ + Name: "identity_signature_operation_duration_seconds", + Help: "Histogram of signer/verifier service operation wall-clock time in seconds, labeled by operation", + LabelNames: []string{"network", "channel", "namespace", "op"}, + Buckets: []float64{.0005, .001, .005, .01, .025, .05, .1, .25, .5, 1, 2.5, 5, 10}, + NativeHistogramBucketFactor: 1.1, + NativeHistogramMaxBucketNumber: 100, + }), + SignerCacheLookups: p.NewCounter(metrics.CounterOpts{ + Name: "identity_signer_cache_lookups_total", + Help: "Total number of signer cache lookups by result (hit, miss)", + LabelNames: []string{"network", "channel", "namespace", "result"}, + }), + ThrottleEscalations: p.NewCounter(metrics.CounterOpts{ + Name: "identity_throttle_escalations_total", + Help: "Total number of throttle level changes by the level entered and the reason", + LabelNames: []string{"network", "channel", "namespace", "level", "reason"}, + }), + ThrottledPrincipals: p.NewGauge(metrics.GaugeOpts{ + Name: "identity_throttled_principals", + Help: "Number of principals currently held at each throttle level above normal", + LabelNames: []string{"network", "channel", "namespace", "level"}, + }), } } @@ -71,3 +129,52 @@ func newMetrics(p metrics.Provider) *Metrics { func NewMetrics(p metrics.Provider) *Metrics { return newMetrics(p) } + +// Observe implements sigobserve.Observer: it records e in the signature instruments. Escalation +// events, which report policy state rather than a service call, are counted separately and +// contribute no duration. +func (m *Metrics) Observe(_ context.Context, e sigobserve.Event) { + if m == nil { + return + } + + if e.Op == sigobserve.OpEscalation { + m.ThrottleEscalations.With("level", e.Level, "reason", e.Reason).Add(1) + + return + } + + m.SignatureOps.With("op", string(e.Op), "role", roleLabel(e.Role), "outcome", string(e.Outcome)).Add(1) + m.SignatureOpDuration.With("op", string(e.Op)).Observe(e.Duration.Seconds()) + if e.CacheChecked { + m.SignerCacheLookups.With("result", cacheLabel(e.CacheHit)).Add(1) + } +} + +// SetThrottledPrincipals implements throttle.LevelGauge. +func (m *Metrics) SetThrottledPrincipals(level string, n int) { + if m == nil { + return + } + + m.ThrottledPrincipals.With("level", level).Set(float64(n)) +} + +// roleLabel keeps the role label from ever being empty, so the label set of every series is the +// same and Prometheus does not see two variants of the same metric. +func roleLabel(role sigobserve.Role) string { + if role == "" { + return string(sigobserve.RoleUnknown) + } + + return string(role) +} + +// cacheLabel renders a cache lookup result. +func cacheLabel(hit bool) string { + if hit { + return "hit" + } + + return "miss" +} diff --git a/token/services/identity/metrics_test.go b/token/services/identity/metrics_test.go new file mode 100644 index 0000000000..4c6edc6c41 --- /dev/null +++ b/token/services/identity/metrics_test.go @@ -0,0 +1,150 @@ +/* +Copyright IBM Corp. All Rights Reserved. + +SPDX-License-Identifier: Apache-2.0 +*/ + +package identity_test + +import ( + "testing" + "time" + + "github.com/LFDT-Panurus/panurus/token/services/identity" + "github.com/LFDT-Panurus/panurus/token/services/identity/sigobserve" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +// tmsLabels are the labels every TMS-scoped metric must declare first, in this order: the +// provider prepends the network/channel/namespace values, so a metric that omits them makes +// Prometheus reject the series with an inconsistent label cardinality. +var tmsLabels = []string{"network", "channel", "namespace"} + +// TestMetricsDeclareTMSLabelsFirst guards the whole metric set at once, since a missing leading +// label is not a compile error and only shows up as a panic in a deployment with a real registry. +func TestMetricsDeclareTMSLabelsFirst(t *testing.T) { + provider := newFakeMetricsProvider() + identity.NewMetrics(provider) + + expected := []string{ + "identity_signer_resolutions_total", + "identity_get_signer_duration_seconds", + "identity_signer_router_registrations_total", + "identity_signer_router_no_probe_errors_total", + "identity_signature_operations_total", + "identity_signature_operation_duration_seconds", + "identity_signer_cache_lookups_total", + "identity_throttle_escalations_total", + "identity_throttled_principals", + } + for _, name := range expected { + labels, ok := provider.declaredLabels[name] + require.True(t, ok, "metric [%s] is not registered", name) + require.GreaterOrEqual(t, len(labels), len(tmsLabels), "metric [%s] declares too few labels", name) + assert.Equal(t, tmsLabels, labels[:len(tmsLabels)], "metric [%s] must declare the TMS labels first", name) + } +} + +func TestMetricsObserveSignatureOperation(t *testing.T) { + provider := newFakeMetricsProvider() + m := identity.NewMetrics(provider) + + m.Observe(t.Context(), sigobserve.Event{ + Op: sigobserve.OpVerify, + Role: sigobserve.RoleOwner, + Outcome: sigobserve.OutcomeInvalid, + Duration: 5 * time.Millisecond, + }) + + assert.Equal(t, 1, provider.counterAddCount("identity_signature_operations_total", + "op", "verify", "role", "owner", "outcome", "invalid")) + assert.Equal(t, 1, provider.histogramObserveCount("identity_signature_operation_duration_seconds", "op", "verify")) + assert.Equal(t, 0, provider.counterAddCount("identity_signer_cache_lookups_total", "result", "hit"), + "an operation that consults no cache must not report a lookup") +} + +// TestMetricsObserveRoleIsNeverEmpty pins the label-cardinality invariant: an empty role would +// register a second variant of the same series. +func TestMetricsObserveRoleIsNeverEmpty(t *testing.T) { + provider := newFakeMetricsProvider() + m := identity.NewMetrics(provider) + + m.Observe(t.Context(), sigobserve.Event{Op: sigobserve.OpBind, Outcome: sigobserve.OutcomeOK}) + + assert.Equal(t, 1, provider.counterAddCount("identity_signature_operations_total", + "op", "bind", "role", "unknown", "outcome", "ok")) +} + +func TestMetricsObserveCacheLookups(t *testing.T) { + tests := []struct { + name string + event sigobserve.Event + result string + }{ + { + name: "hit", + event: sigobserve.Event{Op: sigobserve.OpGetSigner, Outcome: sigobserve.OutcomeOK, Path: sigobserve.PathCache, CacheChecked: true, CacheHit: true}, + result: "hit", + }, + { + name: "miss", + event: sigobserve.Event{Op: sigobserve.OpGetSigner, Outcome: sigobserve.OutcomeOK, Path: sigobserve.PathFallback, CacheChecked: true}, + result: "miss", + }, + } + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + provider := newFakeMetricsProvider() + identity.NewMetrics(provider).Observe(t.Context(), test.event) + + assert.Equal(t, 1, provider.counterAddCount("identity_signer_cache_lookups_total", "result", test.result)) + }) + } +} + +func TestMetricsObserveEscalation(t *testing.T) { + provider := newFakeMetricsProvider() + m := identity.NewMetrics(provider) + + m.Observe(t.Context(), sigobserve.Event{ + Op: sigobserve.OpEscalation, + Outcome: sigobserve.OutcomeOK, + Level: "blocked", + Reason: "invalid_signature_rate", + }) + + assert.Equal(t, 1, provider.counterAddCount("identity_throttle_escalations_total", + "level", "blocked", "reason", "invalid_signature_rate")) + assert.Equal(t, 0, provider.counterAddCount("identity_signature_operations_total", + "op", "escalation", "role", "unknown", "outcome", "ok"), + "policy state must not be counted as a service call") + assert.Equal(t, 0, provider.histogramObserveCount("identity_signature_operation_duration_seconds", "op", "escalation")) +} + +func TestMetricsSetThrottledPrincipals(t *testing.T) { + provider := newFakeMetricsProvider() + m := identity.NewMetrics(provider) + + m.SetThrottledPrincipals("soft", 3) + m.SetThrottledPrincipals("blocked", 1) + + soft, ok := provider.gaugeSetValue("identity_throttled_principals", "level", "soft") + require.True(t, ok) + assert.InDelta(t, 3.0, soft, 0) + blocked, ok := provider.gaugeSetValue("identity_throttled_principals", "level", "blocked") + require.True(t, ok) + assert.InDelta(t, 1.0, blocked, 0) +} + +// TestMetricsToleratesNilReceiverAndProvider covers the two ways a caller can end up without +// instrumentation: no metrics at all, or a provider that discards everything. +func TestMetricsToleratesNilReceiverAndProvider(t *testing.T) { + var m *identity.Metrics + m.Observe(t.Context(), sigobserve.Event{Op: sigobserve.OpSign}) + m.SetThrottledPrincipals("soft", 1) + + m = identity.NewMetrics(nil) + m.Observe(t.Context(), sigobserve.Event{Op: sigobserve.OpSign, Outcome: sigobserve.OutcomeOK}) + m.SetThrottledPrincipals("soft", 1) +} diff --git a/token/services/identity/metrics_test_helpers_test.go b/token/services/identity/metrics_test_helpers_test.go index d8fc034d40..64ee23b4b1 100644 --- a/token/services/identity/metrics_test_helpers_test.go +++ b/token/services/identity/metrics_test_helpers_test.go @@ -25,24 +25,36 @@ type labelRecord struct { type fakeMetricsProvider struct { counterRecords map[string][]labelRecord histogramRecords map[string][]labelRecord + gaugeRecords map[string][]labelRecord + // declaredLabels is the LabelNames each metric was declared with, so that a test can assert + // the label set a Prometheus registry would be handed. + declaredLabels map[string][]string } func newFakeMetricsProvider() *fakeMetricsProvider { return &fakeMetricsProvider{ counterRecords: map[string][]labelRecord{}, histogramRecords: map[string][]labelRecord{}, + gaugeRecords: map[string][]labelRecord{}, + declaredLabels: map[string][]string{}, } } func (p *fakeMetricsProvider) NewCounter(opts metrics.CounterOpts) metrics.Counter { + p.declaredLabels[opts.Name] = opts.LabelNames + return &fakeCounter{provider: p, name: opts.Name} } -func (p *fakeMetricsProvider) NewGauge(_ metrics.GaugeOpts) metrics.Gauge { - return &fakeGauge{} +func (p *fakeMetricsProvider) NewGauge(opts metrics.GaugeOpts) metrics.Gauge { + p.declaredLabels[opts.Name] = opts.LabelNames + + return &fakeGauge{provider: p, name: opts.Name} } func (p *fakeMetricsProvider) NewHistogram(opts metrics.HistogramOpts) metrics.Histogram { + p.declaredLabels[opts.Name] = opts.LabelNames + return &fakeHistogram{provider: p, name: opts.Name} } @@ -100,8 +112,33 @@ func (h *fakeHistogram) Observe(value float64) { h.provider.histogramRecords[h.name] = append(h.provider.histogramRecords[h.name], labelRecord{labels: h.labels, value: value}) } -type fakeGauge struct{} +// gaugeSetValue returns the last value the named gauge was Set to under exactly the given label +// values (in order), and whether it was set at all. +func (p *fakeMetricsProvider) gaugeSetValue(name string, labelValues ...string) (float64, bool) { + value, found := 0.0, false + for _, r := range p.gaugeRecords[name] { + if slices.Equal(r.labels, labelValues) { + value, found = r.value, true + } + } + + return value, found +} + +type fakeGauge struct { + provider *fakeMetricsProvider + name string + labels []string +} -func (g *fakeGauge) With(_ ...string) metrics.Gauge { return g } -func (g *fakeGauge) Add(_ float64) {} -func (g *fakeGauge) Set(_ float64) {} +func (g *fakeGauge) With(labelValues ...string) metrics.Gauge { + return &fakeGauge{provider: g.provider, name: g.name, labels: append(slices.Clone(g.labels), labelValues...)} +} + +func (g *fakeGauge) Add(delta float64) { + g.provider.gaugeRecords[g.name] = append(g.provider.gaugeRecords[g.name], labelRecord{labels: g.labels, value: delta}) +} + +func (g *fakeGauge) Set(value float64) { + g.provider.gaugeRecords[g.name] = append(g.provider.gaugeRecords[g.name], labelRecord{labels: g.labels, value: value}) +} diff --git a/token/services/identity/provider.go b/token/services/identity/provider.go index 0952394cbb..1a008bb606 100644 --- a/token/services/identity/provider.go +++ b/token/services/identity/provider.go @@ -13,6 +13,7 @@ import ( "github.com/LFDT-Panurus/panurus/token/driver" idriver "github.com/LFDT-Panurus/panurus/token/services/identity/driver" + "github.com/LFDT-Panurus/panurus/token/services/identity/sigobserve" "github.com/LFDT-Panurus/panurus/token/services/logging" "github.com/hyperledger-labs/fabric-smart-client/pkg/utils/errors" "github.com/hyperledger-labs/fabric-smart-client/platform/common/utils/cache/secondcache" @@ -87,6 +88,7 @@ type Provider struct { deserializer Deserializer signerRouter *SignerRouter metrics *Metrics + observer sigobserve.Observer signers cache[*SignerEntry] } @@ -113,9 +115,20 @@ func NewProvider( storage: storage, signers: secondcache.NewTyped[*SignerEntry](50), metrics: m, + observer: sigobserve.Nop, } } +// SetObserver installs the observer that this provider's operations, and the signers it hands +// out, are reported to. Passing nil restores the no-op observer, which is the default and costs +// nothing on the signing path. +func (p *Provider) SetObserver(o sigobserve.Observer) { + if o == nil { + o = sigobserve.Nop + } + p.observer = o +} + // SetSignerRouter sets the router consulted for conf_id-pinned signer resolution before falling // back to the linear-scan deserializer. Passing nil disables routing (the default), leaving // GetSigner's fallback behavior unchanged. @@ -131,7 +144,20 @@ func (p *Provider) RegisterRecipientData(ctx context.Context, data *driver.Recip // RegisterSigner registers a Signer and a Verifier for passed identity. // This is implemented via an invocation of RegisterIdentityDescriptor using an IdentityDescriptor with empty AuditInfo. // The audit info might or might not be already stored. +// +// Because of that delegation, an observed RegisterSigner call also produces a +// register_identity_descriptor event; the two ops are reported separately so that direct +// descriptor registrations remain distinguishable from signer registrations. func (p *Provider) RegisterSigner(ctx context.Context, identity driver.Identity, signer driver.Signer, verifier driver.Verifier, signerInfo []byte, ephemeral bool) error { + t := sigobserve.Start(p.observer, sigobserve.OpRegisterSigner, identity.UniqueID(), sigobserve.RoleUnknown) + err := p.registerSigner(ctx, identity, signer, verifier, signerInfo, ephemeral) + t.Done(ctx, err) + + return err +} + +// registerSigner performs the registration RegisterSigner reports on. +func (p *Provider) registerSigner(ctx context.Context, identity driver.Identity, signer driver.Signer, verifier driver.Verifier, signerInfo []byte, ephemeral bool) error { identityDescriptor := &idriver.IdentityDescriptor{ Identity: identity, AuditInfo: nil, @@ -151,7 +177,16 @@ func (p *Provider) RegisterSigner(ctx context.Context, identity driver.Identity, func (p *Provider) AreMe(ctx context.Context, identities ...driver.Identity) []string { p.Logger.DebugfContext(ctx, "identity [%s] is me?", identities) - return p.areMe(ctx, identities...) + t := sigobserve.Start(p.observer, sigobserve.OpIsMe, batchPrincipal(identities), sigobserve.RoleUnknown) + result, err := p.areMe(ctx, identities...) + t.Done(ctx, err) + if err != nil { + // The lookup is best-effort by contract: the identities found before the failure are + // still returned, and the failure is reported through the log and the observer. + p.Logger.Errorf("failed checking if a signer exists [%s]", err) + } + + return result } // IsMe returns true if a signer was ever registered for the passed identity @@ -162,7 +197,11 @@ func (p *Provider) IsMe(ctx context.Context, identity driver.Identity) bool { // GetAuditInfo returns the audit information associated to the passed identity, nil otherwise. // The audit info is retrieved from the configured storage. func (p *Provider) GetAuditInfo(ctx context.Context, identity driver.Identity) ([]byte, error) { - return p.storage.GetAuditInfo(ctx, identity) + t := sigobserve.Start(p.observer, sigobserve.OpGetAuditInfo, identity.UniqueID(), sigobserve.RoleUnknown) + auditInfo, err := p.storage.GetAuditInfo(ctx, identity) + t.Done(ctx, err) + + return auditInfo, err } // GetSigner returns a Signer for passed identity. @@ -197,6 +236,15 @@ func (p *Provider) GetRevocationHandler(ctx context.Context, identity driver.Ide // Bind binds longTerm to the passed ephemeral identities. func (p *Provider) Bind(ctx context.Context, longTerm driver.Identity, ephemeralIdentities ...driver.Identity) error { + t := sigobserve.Start(p.observer, sigobserve.OpBind, longTerm.UniqueID(), sigobserve.RoleUnknown) + err := p.bind(ctx, longTerm, ephemeralIdentities...) + t.Done(ctx, err) + + return err +} + +// bind performs the binding Bind reports on. +func (p *Provider) bind(ctx context.Context, longTerm driver.Identity, ephemeralIdentities ...driver.Identity) error { for _, identity := range ephemeralIdentities { if identity.Equal(longTerm) { // no action required @@ -228,6 +276,15 @@ func (p *Provider) RollbackPartialRecipientRegistration(ctx context.Context, id // RegisterIdentityDescriptor stores the given identity descriptor in the configured storage. // If alias is not nil, the alias can be used as an alternative to `idriver.IdentityDescriptor#Identity`. func (p *Provider) RegisterIdentityDescriptor(ctx context.Context, identityDescriptor *idriver.IdentityDescriptor, alias driver.Identity) error { + t := sigobserve.Start(p.observer, sigobserve.OpRegisterIdentityDescriptor, identityDescriptor.Identity.UniqueID(), sigobserve.RoleUnknown) + err := p.registerIdentityDescriptor(ctx, identityDescriptor, alias) + t.Done(ctx, err) + + return err +} + +// registerIdentityDescriptor performs the registration RegisterIdentityDescriptor reports on. +func (p *Provider) registerIdentityDescriptor(ctx context.Context, identityDescriptor *idriver.IdentityDescriptor, alias driver.Identity) error { // register in the Storage if !identityDescriptor.Ephemeral { if err := p.storage.RegisterIdentityDescriptor(ctx, identityDescriptor, alias); err != nil { @@ -243,7 +300,10 @@ func (p *Provider) RegisterIdentityDescriptor(ctx context.Context, identityDescr return nil } -func (p *Provider) areMe(ctx context.Context, identities ...driver.Identity) []string { +// areMe resolves which of the passed identities have a signer. A storage failure is returned +// rather than swallowed so that the caller can report it, and the identities resolved from the +// cache are returned alongside it. +func (p *Provider) areMe(ctx context.Context, identities ...driver.Identity) ([]string, error) { p.Logger.DebugfContext(ctx, "is me [%s]?", identities) idHashes := make([]string, len(identities)) for i, id := range identities { @@ -264,30 +324,43 @@ func (p *Provider) areMe(ctx context.Context, identities ...driver.Identity) []s } if len(notFound) == 0 { - return result.ToSlice() + return result.ToSlice(), nil } // check Storage found, err := p.storage.GetExistingSignerInfo(ctx, notFound...) if err != nil { - p.Logger.Errorf("failed checking if a signer exists [%s]", err) - - return result.ToSlice() + return result.ToSlice(), errors.Wrapf(err, "failed checking if a signer exists") } result.Add(found...) - return result.ToSlice() + return result.ToSlice(), nil +} + +// batchPrincipal attributes an operation performed over a set of identities. A single identity +// is attributed to itself; a batch is left unattributed, since charging a whole batch to one of +// its members would let unrelated identities throttle each other. +func batchPrincipal(identities []driver.Identity) string { + if len(identities) != 1 { + return "" + } + + return identities[0].UniqueID() } +// getSigner resolves the signer for identity, reporting the resolution and wrapping the result so +// that the signatures it produces are observed too. func (p *Provider) getSigner(ctx context.Context, identity driver.Identity, idHash string) (driver.Signer, error) { + t := sigobserve.Start(p.observer, sigobserve.OpGetSigner, idHash, sigobserve.RoleUnknown) start := time.Now() signer, _, path, err := p.getSignerAndCache(ctx, identity, idHash, true) p.metrics.GetSignerDuration.With("path", path).Observe(time.Since(start).Seconds()) if err == nil { p.metrics.SignerResolutions.With("outcome", path).Add(1) } + t.DoneResolution(ctx, path, err) - return signer, err + return sigobserve.InstrumentSigner(signer, p.observer, idHash, sigobserve.RoleUnknown), err } // getSignerAndCache resolves the signer for identity. The returned path reports how the signer @@ -300,7 +373,7 @@ func (p *Provider) getSignerAndCache(ctx context.Context, identity driver.Identi if entry, ok := p.signers.Get(idHash); ok { p.Logger.DebugfContext(ctx, "signer for [%s] found", idHash) - return entry.Signer, false, "cache", nil + return entry.Signer, false, sigobserve.PathCache, nil } p.Logger.DebugfContext(ctx, "signer for [%s] not found, attempting to deserialize", idHash) @@ -312,24 +385,24 @@ func (p *Provider) getSignerAndCache(ctx context.Context, identity driver.Identi if signer, ok := p.signerRouter.Resolve(ctx, identity); ok { signer, shouldCache, err := p.cacheAndPersistSigner(ctx, identity, idHash, signer, shouldCache) - return signer, shouldCache, "routed", err + return signer, shouldCache, sigobserve.PathRouted, err } } // check that we have a deserializer if p.deserializer == nil { - return nil, false, "fallback", errors.Errorf("cannot find signer for [%s], no deserializer set", identity) + return nil, false, sigobserve.PathFallback, errors.Errorf("cannot find signer for [%s], no deserializer set", identity) } // try direct deserialization signer, err := p.deserializer.DeserializeSigner(ctx, identity) - path := "fallback" + path := sigobserve.PathFallback if err != nil { // second chance: try a TypedIdentity typed, err2 := UnmarshalTypedIdentity(identity) if err2 != nil { // neither deserializable nor a typed wrapper - return nil, false, "fallback", errors.Wrapf( + return nil, false, sigobserve.PathFallback, errors.Wrapf( err2, "failed to unmarshal typed identity for [%s] and failed deserialization [%s]", identity.String(), err, diff --git a/token/services/identity/provider_observe_bench_test.go b/token/services/identity/provider_observe_bench_test.go new file mode 100644 index 0000000000..b5da07dd6b --- /dev/null +++ b/token/services/identity/provider_observe_bench_test.go @@ -0,0 +1,131 @@ +/* +Copyright IBM Corp. All Rights Reserved. + +SPDX-License-Identifier: Apache-2.0 +*/ + +package identity_test + +import ( + "testing" + + "github.com/LFDT-Panurus/panurus/token/driver" + drvmock "github.com/LFDT-Panurus/panurus/token/driver/mock" + "github.com/LFDT-Panurus/panurus/token/services/identity" + idmock "github.com/LFDT-Panurus/panurus/token/services/identity/mock" + "github.com/LFDT-Panurus/panurus/token/services/identity/sigobserve" + "github.com/LFDT-Panurus/panurus/token/services/identity/sigpolicy" + "github.com/LFDT-Panurus/panurus/token/services/identity/throttle" + "github.com/LFDT-Panurus/panurus/token/services/logging" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +// BenchmarkGetSignerAndSign measures the hot path with instrumentation off and with the full +// stack (metrics, audit log, throttle policy) installed. Signing happens once per transaction, +// so the difference between the two is the price of the feature and belongs in review. +func BenchmarkGetSignerAndSign(b *testing.B) { + id := driver.Identity("an_identity") + message := []byte("message") + + newProvider := func(b *testing.B) *identity.Provider { + b.Helper() + + signer := &drvmock.Signer{} + signer.SignReturns([]byte("sigma"), nil) + des := &idmock.Deserializer{} + des.DeserializeSignerReturns(signer, nil) + + return identity.NewProvider(logging.MustGetLogger(), &idmock.Storage{}, des, + &idmock.NetworkBinderService{}, &idmock.EnrollmentIDUnmarshaler{}, identity.NewMetrics(nil)) + } + + run := func(b *testing.B, p *identity.Provider) { + b.Helper() + ctx := b.Context() + + // Warm the signer cache: the steady state of a signing node is a cache hit. + _, err := p.GetSigner(ctx, id) + require.NoError(b, err) + + b.ReportAllocs() + b.ResetTimer() + for range b.N { + signer, err := p.GetSigner(ctx, id) + if err != nil { + b.Fatal(err) + } + if _, err := signer.Sign(message); err != nil { + b.Fatal(err) + } + } + } + + b.Run("observer off", func(b *testing.B) { + run(b, newProvider(b)) + }) + + b.Run("observer on", func(b *testing.B) { + p := newProvider(b) + stack, err := sigpolicy.New(logging.MustGetLogger(), nil, identity.NewMetrics(nil)) + require.NoError(b, err) + b.Cleanup(stack.Stop) + p.SetObserver(stack.Observer()) + + run(b, p) + }) +} + +// TestGetSignerAndSignDisabledAllocatesNothing pins the zero-cost claim behind "observer off" +// above: a throttle policy configured off, with neither metrics nor a logger, must collapse to +// sigobserve.Nop so that signing and verifying are unwrapped and the hot path allocates nothing +// extra. A regression here would mean "off" no longer means "feature absent". +func TestGetSignerAndSignDisabledAllocatesNothing(t *testing.T) { + stack, err := sigpolicy.New(nil, nil, nil) + require.NoError(t, err) + t.Cleanup(stack.Stop) + + assert.Equal(t, throttle.ModeMonitor, stack.Config().Mode, "the default mode is monitor, not off; disable it explicitly below") + + offStack, err := sigpolicy.New(nil, &fixedModeConfigService{mode: throttle.ModeOff}, nil) + require.NoError(t, err) + t.Cleanup(offStack.Stop) + + assert.Equal(t, sigobserve.Nop, offStack.Observer(), "mode off with no sinks must collapse to Nop") + + sigma := []byte("sigma") + signer := plainSigner{sigma: sigma} + wrapped := sigobserve.InstrumentSigner(signer, offStack.Observer(), "principal", sigobserve.RoleUnknown) + message := []byte("message") + + allocs := testing.AllocsPerRun(100, func() { + if _, err := wrapped.Sign(message); err != nil { + t.Fatal(err) + } + }) + assert.InDelta(t, 0.0, allocs, 0, "signing through a disabled stack's observer must not allocate") +} + +// plainSigner is a driver.Signer with no recording overhead of its own, so that a benchmark or +// allocation assertion measures only the cost the wrapper adds. +type plainSigner struct { + sigma []byte +} + +func (s plainSigner) Sign([]byte) ([]byte, error) { return s.sigma, nil } + +// fixedModeConfigService serves a throttle configuration with only Mode set, letting the rest +// default. +type fixedModeConfigService struct { + mode throttle.Mode +} + +func (c *fixedModeConfigService) UnmarshalKey(_ string, rawVal any) error { + cfg, ok := rawVal.(*throttle.Config) + if !ok { + return nil + } + cfg.Mode = c.mode + + return nil +} diff --git a/token/services/identity/provider_observe_test.go b/token/services/identity/provider_observe_test.go new file mode 100644 index 0000000000..ce7bf8bef3 --- /dev/null +++ b/token/services/identity/provider_observe_test.go @@ -0,0 +1,258 @@ +/* +Copyright IBM Corp. All Rights Reserved. + +SPDX-License-Identifier: Apache-2.0 +*/ + +package identity_test + +import ( + "context" + "sync" + "testing" + + "github.com/LFDT-Panurus/panurus/token/driver" + drvmock "github.com/LFDT-Panurus/panurus/token/driver/mock" + "github.com/LFDT-Panurus/panurus/token/services/identity" + idmock "github.com/LFDT-Panurus/panurus/token/services/identity/mock" + "github.com/LFDT-Panurus/panurus/token/services/identity/sigobserve" + "github.com/LFDT-Panurus/panurus/token/services/logging" + "github.com/hyperledger-labs/fabric-smart-client/pkg/utils/errors" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +// eventRecorder collects the events an instrumented component reports. +type eventRecorder struct { + mu sync.Mutex + events []sigobserve.Event +} + +func (r *eventRecorder) Observe(_ context.Context, e sigobserve.Event) { + r.mu.Lock() + defer r.mu.Unlock() + r.events = append(r.events, e) +} + +func (r *eventRecorder) all() []sigobserve.Event { + r.mu.Lock() + defer r.mu.Unlock() + + return append([]sigobserve.Event(nil), r.events...) +} + +// byOp returns the events reported for op. +func (r *eventRecorder) byOp(op sigobserve.Op) []sigobserve.Event { + out := make([]sigobserve.Event, 0, 1) + for _, e := range r.all() { + if e.Op == op { + out = append(out, e) + } + } + + return out +} + +// oneOf returns the single event reported for op. +func (r *eventRecorder) oneOf(t *testing.T, op sigobserve.Op) sigobserve.Event { + t.Helper() + events := r.byOp(op) + require.Len(t, events, 1, "expected exactly one [%s] event", op) + + return events[0] +} + +// observedProvider is a Provider wired to a recorder, with its collaborators exposed. +type observedProvider struct { + provider *identity.Provider + storage *idmock.Storage + des *idmock.Deserializer + binder *idmock.NetworkBinderService + events *eventRecorder +} + +func newObservedProvider(t *testing.T) *observedProvider { + t.Helper() + + o := &observedProvider{ + storage: &idmock.Storage{}, + des: &idmock.Deserializer{}, + binder: &idmock.NetworkBinderService{}, + events: &eventRecorder{}, + } + o.provider = identity.NewProvider(logging.MustGetLogger(), o.storage, o.des, o.binder, &idmock.EnrollmentIDUnmarshaler{}, nil) + o.provider.SetObserver(o.events) + + return o +} + +func TestProviderObservesGetSigner(t *testing.T) { + o := newObservedProvider(t) + signer := &drvmock.Signer{} + signer.SignReturns([]byte("sigma"), nil) + o.des.DeserializeSignerReturns(signer, nil) + + id := driver.Identity("an_identity") + resolved, err := o.provider.GetSigner(t.Context(), id) + require.NoError(t, err) + + event := o.events.oneOf(t, sigobserve.OpGetSigner) + assert.Equal(t, id.UniqueID(), event.Principal, "a principal is named by identity hash") + assert.Equal(t, sigobserve.OutcomeOK, event.Outcome) + assert.Equal(t, sigobserve.PathFallback, event.Path) + assert.True(t, event.CacheChecked) + assert.False(t, event.CacheHit) + + // The resolved signer is instrumented too, so the signatures it produces are attributed. + _, err = resolved.Sign([]byte("message")) + require.NoError(t, err) + signEvent := o.events.oneOf(t, sigobserve.OpSign) + assert.Equal(t, id.UniqueID(), signEvent.Principal) + assert.Equal(t, sigobserve.OutcomeOK, signEvent.Outcome) +} + +func TestProviderObservesGetSignerCacheHit(t *testing.T) { + o := newObservedProvider(t) + o.des.DeserializeSignerReturns(&drvmock.Signer{}, nil) + + id := driver.Identity("an_identity") + _, err := o.provider.GetSigner(t.Context(), id) + require.NoError(t, err) + _, err = o.provider.GetSigner(t.Context(), id) + require.NoError(t, err) + + events := o.events.byOp(sigobserve.OpGetSigner) + require.Len(t, events, 2) + assert.Equal(t, sigobserve.PathFallback, events[0].Path) + assert.False(t, events[0].CacheHit) + assert.Equal(t, sigobserve.PathCache, events[1].Path) + assert.True(t, events[1].CacheHit) +} + +func TestProviderObservesGetSignerFailure(t *testing.T) { + o := newObservedProvider(t) + o.des.DeserializeSignerReturns(nil, errors.New("no signer")) + + _, err := o.provider.GetSigner(t.Context(), driver.Identity("an_identity")) + require.Error(t, err) + + event := o.events.oneOf(t, sigobserve.OpGetSigner) + assert.Equal(t, sigobserve.OutcomeError, event.Outcome) + require.Error(t, event.Err) + assert.Empty(t, o.events.byOp(sigobserve.OpSign), "a failed resolution hands out no signer to instrument") +} + +func TestProviderObservesRegisterSigner(t *testing.T) { + o := newObservedProvider(t) + id := driver.Identity("signer_id") + + require.NoError(t, o.provider.RegisterSigner(t.Context(), id, &drvmock.Signer{}, &drvmock.Verifier{}, nil, false)) + + registerEvent := o.events.oneOf(t, sigobserve.OpRegisterSigner) + assert.Equal(t, id.UniqueID(), registerEvent.Principal) + assert.Equal(t, sigobserve.OutcomeOK, registerEvent.Outcome) + + // RegisterSigner delegates to a descriptor registration, and the two are reported separately + // so that a direct descriptor registration stays distinguishable. + descriptorEvent := o.events.oneOf(t, sigobserve.OpRegisterIdentityDescriptor) + assert.Equal(t, id.UniqueID(), descriptorEvent.Principal) +} + +func TestProviderObservesRegisterSignerFailure(t *testing.T) { + o := newObservedProvider(t) + o.storage.RegisterIdentityDescriptorReturns(errors.New("storage down")) + + err := o.provider.RegisterSigner(t.Context(), driver.Identity("signer_id"), &drvmock.Signer{}, &drvmock.Verifier{}, nil, false) + require.Error(t, err) + + assert.Equal(t, sigobserve.OutcomeError, o.events.oneOf(t, sigobserve.OpRegisterSigner).Outcome) + assert.Equal(t, sigobserve.OutcomeError, o.events.oneOf(t, sigobserve.OpRegisterIdentityDescriptor).Outcome) +} + +func TestProviderObservesBind(t *testing.T) { + o := newObservedProvider(t) + longTerm := driver.Identity("long_term") + + require.NoError(t, o.provider.Bind(t.Context(), longTerm, driver.Identity("ephemeral"))) + + event := o.events.oneOf(t, sigobserve.OpBind) + assert.Equal(t, longTerm.UniqueID(), event.Principal, "a binding is attributed to the long-term identity") + assert.Equal(t, sigobserve.OutcomeOK, event.Outcome) +} + +func TestProviderObservesGetAuditInfo(t *testing.T) { + o := newObservedProvider(t) + id := driver.Identity("an_identity") + o.storage.GetAuditInfoReturns(nil, errors.New("storage down")) + + _, err := o.provider.GetAuditInfo(t.Context(), id) + require.Error(t, err) + + event := o.events.oneOf(t, sigobserve.OpGetAuditInfo) + assert.Equal(t, id.UniqueID(), event.Principal) + assert.Equal(t, sigobserve.OutcomeError, event.Outcome) +} + +func TestProviderObservesAreMe(t *testing.T) { + t.Run("a single identity is attributed to itself", func(t *testing.T) { + o := newObservedProvider(t) + id := driver.Identity("an_identity") + o.storage.GetExistingSignerInfoReturns([]string{id.UniqueID()}, nil) + + assert.Len(t, o.provider.AreMe(t.Context(), id), 1) + + event := o.events.oneOf(t, sigobserve.OpIsMe) + assert.Equal(t, id.UniqueID(), event.Principal) + assert.Equal(t, sigobserve.OutcomeOK, event.Outcome) + }) + + t.Run("a batch is left unattributed", func(t *testing.T) { + o := newObservedProvider(t) + o.storage.GetExistingSignerInfoReturns(nil, nil) + + o.provider.AreMe(t.Context(), driver.Identity("first"), driver.Identity("second")) + + event := o.events.oneOf(t, sigobserve.OpIsMe) + assert.Empty(t, event.Principal, "charging a batch to one of its members would let identities throttle each other") + }) +} + +// TestProviderReportsAreMeStorageFailure covers the contract of a best-effort lookup: the +// identities resolved before the failure are still returned, and the failure is still reported. +func TestProviderReportsAreMeStorageFailure(t *testing.T) { + o := newObservedProvider(t) + cached := driver.Identity("cached_identity") + require.NoError(t, o.provider.RegisterSigner(t.Context(), cached, &drvmock.Signer{}, &drvmock.Verifier{}, nil, true)) + o.storage.GetExistingSignerInfoReturns(nil, errors.New("storage down")) + + result := o.provider.AreMe(t.Context(), cached, driver.Identity("unknown_identity")) + assert.Equal(t, []string{cached.UniqueID()}, result, "what the cache knew is still returned") + + event := o.events.oneOf(t, sigobserve.OpIsMe) + assert.Equal(t, sigobserve.OutcomeError, event.Outcome, "a swallowed storage failure is invisible; this one is not") + assert.ErrorContains(t, event.Err, "failed checking if a signer exists") +} + +func TestProviderIsMeReportsOneEvent(t *testing.T) { + o := newObservedProvider(t) + id := driver.Identity("an_identity") + o.storage.GetExistingSignerInfoReturns([]string{id.UniqueID()}, nil) + + assert.True(t, o.provider.IsMe(t.Context(), id)) + assert.Len(t, o.events.byOp(sigobserve.OpIsMe), 1, "IsMe is AreMe of one identity, not two operations") +} + +// TestProviderWithoutObserverIsTransparent pins the zero-cost default: with no observer the +// provider hands back the signer it resolved, unwrapped, so nothing about the signing path changes. +func TestProviderWithoutObserverIsTransparent(t *testing.T) { + o := newObservedProvider(t) + expected := &drvmock.Signer{} + o.des.DeserializeSignerReturns(expected, nil) + + o.provider.SetObserver(nil) + + resolved, err := o.provider.GetSigner(t.Context(), driver.Identity("an_identity")) + require.NoError(t, err) + assert.Same(t, expected, resolved) + assert.Empty(t, o.events.all()) +} diff --git a/token/services/identity/sigobserve/audit.go b/token/services/identity/sigobserve/audit.go new file mode 100644 index 0000000000..713c1108c6 --- /dev/null +++ b/token/services/identity/sigobserve/audit.go @@ -0,0 +1,172 @@ +/* +Copyright IBM Corp. All Rights Reserved. + +SPDX-License-Identifier: Apache-2.0 +*/ + +package sigobserve + +import ( + "context" + "strconv" + "strings" + + "go.uber.org/zap/zapcore" +) + +// auditLog is the subset of logging.Logger the audit trail needs. Keeping it narrow lets the +// audit record be asserted in tests without a logging backend. +type auditLog interface { + // DebugfContext logs at debug level. + DebugfContext(ctx context.Context, template string, args ...any) + // InfofContext logs at info level. + InfofContext(ctx context.Context, template string, args ...any) + // WarnfContext logs at warn level. + WarnfContext(ctx context.Context, template string, args ...any) +} + +// levelProbe reports whether a log level is enabled. logging.Logger implements it; the +// interface is optional so that a caller can pass any of the three logging methods' provider +// without one. +type levelProbe interface { + // IsEnabledFor reports whether level would be written. + IsEnabledFor(level zapcore.Level) bool +} + +// AuditLogger is an Observer that writes one structured record per operation, providing the +// forensic trail needed to attribute abuse to a principal after the fact. +// +// Level is chosen so that the trail survives a production log level: routine successes are +// debug, while everything an operator would investigate - errors, rejected signatures, +// throttled calls - is warn, and throttle level changes are info. That is deliberate; a +// deployment that wants the full trail turns the logger to debug, but one that does not still +// keeps every anomaly. +// +// Records name the principal by identity hash only. Raw identity bytes are never logged: the +// hash is enough to attribute and correlate, and identity material in a log file is a leak +// that outlives the incident it was meant to document. +type AuditLogger struct { + logger auditLog + // probe, when the logger provides one, tells whether a level is enabled. It is nil for a + // logger without the capability, in which case every record is rendered. + probe levelProbe +} + +// NewAuditLogger returns an AuditLogger writing to logger. +func NewAuditLogger(logger auditLog) *AuditLogger { + a := &AuditLogger{logger: logger} + if probe, ok := logger.(levelProbe); ok { + a.probe = probe + } + + return a +} + +// Observe writes e as one audit record. +func (a *AuditLogger) Observe(ctx context.Context, e Event) { + if a == nil || a.logger == nil { + return + } + + // Rendering a record costs a string build, and this runs once per signature operation. At + // a production log level the routine records are discarded, so they are not built either. + level := levelFor(e) + if a.probe != nil && !a.probe.IsEnabledFor(level) { + return + } + + record := a.record(e) + switch level { + case zapcore.WarnLevel: + a.logger.WarnfContext(ctx, "%s", record) + case zapcore.InfoLevel: + a.logger.InfofContext(ctx, "%s", record) + default: + a.logger.DebugfContext(ctx, "%s", record) + } +} + +// levelFor maps an event to the level its record is written at. Everything an operator would +// investigate - errors, rejected signatures, throttled calls - is warn, a level change is info, +// and routine successes are debug. +func levelFor(e Event) zapcore.Level { + switch e.Outcome { + case OutcomeError, OutcomeInvalid, OutcomeThrottled: + return zapcore.WarnLevel + case OutcomeOK: + if e.Op == OpEscalation { + // A level change is not routine traffic: it is the policy engine acting, and an + // operator reading at info level needs to see it. + return zapcore.InfoLevel + } + + return zapcore.DebugLevel + default: + return zapcore.DebugLevel + } +} + +// record renders e as a stable, greppable key=value line. Field order is fixed so that +// records can be compared and parsed by position as well as by key. +func (a *AuditLogger) record(e Event) string { + var b strings.Builder + // A record is a handful of short fields; one allocation of roughly this size covers it. + b.Grow(160) + + b.WriteString("sig-audit op=") + b.WriteString(string(e.Op)) + b.WriteString(" principal=") + b.WriteString(principalOrNone(e.Principal)) + if e.Role != "" { + b.WriteString(" role=") + b.WriteString(string(e.Role)) + } + b.WriteString(" outcome=") + b.WriteString(string(e.Outcome)) + if e.Path != "" { + b.WriteString(" path=") + b.WriteString(e.Path) + } + if e.CacheChecked { + b.WriteString(" cache=") + b.WriteString(cacheResult(e.CacheHit)) + } + if e.Op != OpEscalation { + b.WriteString(" duration_ms=") + b.WriteString(strconv.FormatFloat(float64(e.Duration.Microseconds())/1000, 'f', 3, 64)) + } + if e.Level != "" { + b.WriteString(" level=") + b.WriteString(e.Level) + } + if e.Reason != "" { + b.WriteString(" reason=") + b.WriteString(e.Reason) + } + if e.Err != nil { + b.WriteString(" err=[") + b.WriteString(e.Err.Error()) + b.WriteString("]") + } + + return b.String() +} + +// principalOrNone renders an empty principal explicitly, so a record is never ambiguous +// about whether attribution was missing or the field was dropped. +func principalOrNone(principal string) string { + if principal == "" { + return "none" + } + + return principal +} + +// cacheResult renders a cache lookup outcome. +func cacheResult(hit bool) string { + if hit { + return "hit" + } + + return "miss" +} diff --git a/token/services/identity/sigobserve/audit_test.go b/token/services/identity/sigobserve/audit_test.go new file mode 100644 index 0000000000..59aa639b75 --- /dev/null +++ b/token/services/identity/sigobserve/audit_test.go @@ -0,0 +1,245 @@ +/* +Copyright IBM Corp. All Rights Reserved. + +SPDX-License-Identifier: Apache-2.0 +*/ + +package sigobserve_test + +import ( + "context" + "fmt" + "strings" + "testing" + "time" + + "github.com/LFDT-Panurus/panurus/token/driver" + "github.com/LFDT-Panurus/panurus/token/services/identity/sigobserve" + "github.com/hyperledger-labs/fabric-smart-client/pkg/utils/errors" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.uber.org/zap/zapcore" +) + +// logLine is one record written by the audit logger, with the level it was written at. +type logLine struct { + level string + text string +} + +// captureLog records what the audit logger writes, at which level. +type captureLog struct { + lines []logLine +} + +func (l *captureLog) DebugfContext(_ context.Context, template string, args ...any) { + l.lines = append(l.lines, logLine{level: "debug", text: fmt.Sprintf(template, args...)}) +} + +func (l *captureLog) InfofContext(_ context.Context, template string, args ...any) { + l.lines = append(l.lines, logLine{level: "info", text: fmt.Sprintf(template, args...)}) +} + +func (l *captureLog) WarnfContext(_ context.Context, template string, args ...any) { + l.lines = append(l.lines, logLine{level: "warn", text: fmt.Sprintf(template, args...)}) +} + +func (l *captureLog) one(t *testing.T) logLine { + t.Helper() + require.Len(t, l.lines, 1) + + return l.lines[0] +} + +func TestAuditLoggerRecord(t *testing.T) { + log := &captureLog{} + audit := sigobserve.NewAuditLogger(log) + + audit.Observe(t.Context(), sigobserve.Event{ + Op: sigobserve.OpGetSigner, + Principal: "abcd1234", + Role: sigobserve.RoleOwner, + Outcome: sigobserve.OutcomeOK, + Path: sigobserve.PathCache, + CacheChecked: true, + CacheHit: true, + Duration: 1500 * time.Microsecond, + }) + + line := log.one(t) + assert.Equal(t, "debug", line.level, "a routine success belongs at debug") + assert.Equal(t, + "sig-audit op=get_signer principal=abcd1234 role=owner outcome=ok path=cache cache=hit duration_ms=1.500", + line.text, + ) +} + +func TestAuditLoggerLevels(t *testing.T) { + tests := []struct { + name string + event sigobserve.Event + level string + }{ + { + name: "success is debug", + event: sigobserve.Event{Op: sigobserve.OpSign, Outcome: sigobserve.OutcomeOK}, + level: "debug", + }, + { + name: "error is warn", + event: sigobserve.Event{Op: sigobserve.OpSign, Outcome: sigobserve.OutcomeError, Err: errors.New("boom")}, + level: "warn", + }, + { + name: "invalid signature is warn", + event: sigobserve.Event{Op: sigobserve.OpVerify, Outcome: sigobserve.OutcomeInvalid}, + level: "warn", + }, + { + name: "throttled is warn", + event: sigobserve.Event{Op: sigobserve.OpGetSigner, Outcome: sigobserve.OutcomeThrottled}, + level: "warn", + }, + { + name: "escalation is info", + event: sigobserve.Event{Op: sigobserve.OpEscalation, Outcome: sigobserve.OutcomeOK, Level: "soft", Reason: "rate"}, + level: "info", + }, + { + name: "an unknown outcome is debug", + event: sigobserve.Event{Op: sigobserve.OpSign, Outcome: sigobserve.Outcome("something-new")}, + level: "debug", + }, + } + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + log := &captureLog{} + sigobserve.NewAuditLogger(log).Observe(t.Context(), test.event) + assert.Equal(t, test.level, log.one(t).level) + }) + } +} + +func TestAuditLoggerEscalationRecord(t *testing.T) { + log := &captureLog{} + sigobserve.NewAuditLogger(log).Observe(t.Context(), sigobserve.Event{ + Op: sigobserve.OpEscalation, + Principal: "abcd1234", + Role: sigobserve.RoleUnknown, + Outcome: sigobserve.OutcomeOK, + Level: "blocked", + Reason: "invalid_signature_rate", + }) + + line := log.one(t) + assert.Equal(t, + "sig-audit op=escalation principal=abcd1234 role=unknown outcome=ok level=blocked reason=invalid_signature_rate", + line.text, + ) + assert.NotContains(t, line.text, "duration_ms", "an escalation reports state, not a call") +} + +func TestAuditLoggerOptionalFields(t *testing.T) { + log := &captureLog{} + sigobserve.NewAuditLogger(log).Observe(t.Context(), sigobserve.Event{ + Op: sigobserve.OpIsMe, + Outcome: sigobserve.OutcomeError, + Err: errors.New("storage down"), + }) + + text := log.one(t).text + assert.Contains(t, text, "principal=none", "a missing attribution must be explicit") + assert.NotContains(t, text, "role=") + assert.NotContains(t, text, "path=") + assert.NotContains(t, text, "cache=") + assert.Contains(t, text, "err=[storage down]") +} + +func TestAuditLoggerCacheMiss(t *testing.T) { + log := &captureLog{} + sigobserve.NewAuditLogger(log).Observe(t.Context(), sigobserve.Event{ + Op: sigobserve.OpGetSigner, + Outcome: sigobserve.OutcomeOK, + Path: sigobserve.PathFallback, + CacheChecked: true, + }) + + assert.Contains(t, log.one(t).text, "cache=miss") +} + +// probingLog is a captureLog that reports which levels it would write. +type probingLog struct { + captureLog + enabled zapcore.Level +} + +func (l *probingLog) IsEnabledFor(level zapcore.Level) bool { return level >= l.enabled } + +// TestAuditLoggerSkipsDisabledLevels covers the hot-path guard: an audit record costs a string +// build, this runs once per signature operation, and at a production log level the routine +// records are thrown away — so they must not be built in the first place. +func TestAuditLoggerSkipsDisabledLevels(t *testing.T) { + log := &probingLog{enabled: zapcore.WarnLevel} + audit := sigobserve.NewAuditLogger(log) + + audit.Observe(t.Context(), sigobserve.Event{Op: sigobserve.OpSign, Principal: "abcd1234", Outcome: sigobserve.OutcomeOK}) + assert.Empty(t, log.lines, "a routine success must not be rendered when debug is off") + + audit.Observe(t.Context(), sigobserve.Event{Op: sigobserve.OpEscalation, Principal: "abcd1234", Outcome: sigobserve.OutcomeOK, Level: "soft"}) + assert.Empty(t, log.lines, "nor an escalation when info is off") + + audit.Observe(t.Context(), sigobserve.Event{Op: sigobserve.OpVerify, Principal: "abcd1234", Outcome: sigobserve.OutcomeInvalid}) + assert.Equal(t, "warn", log.one(t).level, "but an anomaly is still written") +} + +// TestAuditLoggerWithoutAProbeWritesEverything covers a logger that cannot report its level: the +// trail is more valuable than the string build, so every record is rendered. +func TestAuditLoggerWithoutAProbeWritesEverything(t *testing.T) { + log := &captureLog{} + sigobserve.NewAuditLogger(log).Observe(t.Context(), sigobserve.Event{Op: sigobserve.OpSign, Outcome: sigobserve.OutcomeOK}) + + assert.Equal(t, "debug", log.one(t).level) +} + +func TestAuditLoggerToleratesNoLogger(t *testing.T) { + var audit *sigobserve.AuditLogger + audit.Observe(t.Context(), sigobserve.Event{}) + sigobserve.NewAuditLogger(nil).Observe(t.Context(), sigobserve.Event{}) +} + +// TestAuditLoggerNeverLogsIdentityBytes is the privacy guard on the audit trail: the record must +// name a principal by identity hash only, so that identity material cannot leak into a log file +// and outlive the incident the record was written for. +func TestAuditLoggerNeverLogsIdentityBytes(t *testing.T) { + raw := driver.Identity("SECRET-IDENTITY-MATERIAL") + log := &captureLog{} + audit := sigobserve.NewAuditLogger(log) + + ops := []sigobserve.Op{ + sigobserve.OpGetSigner, sigobserve.OpRegisterSigner, sigobserve.OpRegisterIdentityDescriptor, + sigobserve.OpIsMe, sigobserve.OpGetAuditInfo, sigobserve.OpBind, sigobserve.OpOwnerVerifier, + sigobserve.OpIssuerVerifier, sigobserve.OpAuditorVerifier, sigobserve.OpSign, + sigobserve.OpVerify, sigobserve.OpEscalation, + } + outcomes := []sigobserve.Outcome{ + sigobserve.OutcomeOK, sigobserve.OutcomeError, sigobserve.OutcomeInvalid, sigobserve.OutcomeThrottled, + } + for _, op := range ops { + for _, outcome := range outcomes { + audit.Observe(t.Context(), sigobserve.Event{ + Op: op, + Principal: raw.UniqueID(), + Role: sigobserve.RoleOwner, + Outcome: outcome, + Duration: time.Millisecond, + }) + } + } + + require.NotEmpty(t, log.lines) + for _, line := range log.lines { + assert.NotContains(t, line.text, string(raw), "raw identity bytes must never reach the audit log") + assert.Contains(t, line.text, raw.UniqueID()) + assert.True(t, strings.HasPrefix(line.text, "sig-audit op="), "records must stay greppable") + } +} diff --git a/token/services/identity/sigobserve/decorator.go b/token/services/identity/sigobserve/decorator.go new file mode 100644 index 0000000000..1d8d63a9aa --- /dev/null +++ b/token/services/identity/sigobserve/decorator.go @@ -0,0 +1,99 @@ +/* +Copyright IBM Corp. All Rights Reserved. + +SPDX-License-Identifier: Apache-2.0 +*/ + +package sigobserve + +import ( + "context" + + "github.com/LFDT-Panurus/panurus/token/driver" +) + +// InstrumentSigner wraps signer so that every Sign call is reported to o as an OpSign event. +// The wrapper is transparent: it returns exactly what the wrapped signer returns. +// +// When o drops events (nil or Nop) the signer is returned unwrapped, so instrumentation that +// is switched off costs nothing on the signing path. When the wrapped signer is also a +// driver.SigningIdentity, the returned signer is one too, so callers that need Serialize +// keep working through the wrapper. +// +// Events are reported with context.Background(): Sign has no context of its own, and +// storing a resolution-time context in the wrapper would pin a request-scoped span for the +// full lifetime of the signer (which is process lifetime in the common case). The identity +// and role fields on the event are enough for attribution and correlation. +func InstrumentSigner(signer driver.Signer, o Observer, principal string, role Role) driver.Signer { + if signer == nil || o == nil || o == Nop { + return signer + } + + base := instrumentedSigner{signer: signer, observer: o, principal: principal, role: role} + if si, ok := signer.(driver.SigningIdentity); ok { + return &instrumentedSigningIdentity{instrumentedSigner: base, identity: si} + } + + return &base +} + +// InstrumentVerifier wraps verifier so that every Verify call is reported to o as an +// OpVerify event, with a failed verification reported as OutcomeInvalid. The wrapper is +// transparent, and a verifier is returned unwrapped when o drops events. +// +// Events are reported with context.Background() for the same reason as InstrumentSigner. +func InstrumentVerifier(verifier driver.Verifier, o Observer, principal string, role Role) driver.Verifier { + if verifier == nil || o == nil || o == Nop { + return verifier + } + + return &instrumentedVerifier{verifier: verifier, observer: o, principal: principal, role: role} +} + +// instrumentedSigner reports the timing and outcome of each Sign call. +type instrumentedSigner struct { + signer driver.Signer + observer Observer + principal string + role Role +} + +// Sign signs message with the wrapped signer, reporting the call as an OpSign event. +func (s *instrumentedSigner) Sign(message []byte) ([]byte, error) { + t := Start(s.observer, OpSign, s.principal, s.role) + sigma, err := s.signer.Sign(message) + t.Done(context.Background(), err) + + return sigma, err +} + +// instrumentedSigningIdentity is an instrumentedSigner that also forwards Serialize, for +// wrapped signers that are driver.SigningIdentity. +type instrumentedSigningIdentity struct { + instrumentedSigner + identity driver.SigningIdentity +} + +// Serialize returns the byte representation of the wrapped signing identity. It is not +// instrumented: it moves no secret and performs no cryptography. +func (s *instrumentedSigningIdentity) Serialize() ([]byte, error) { + return s.identity.Serialize() +} + +// instrumentedVerifier reports the timing and outcome of each Verify call. +type instrumentedVerifier struct { + verifier driver.Verifier + observer Observer + principal string + role Role +} + +// Verify checks sigma over message with the wrapped verifier, reporting the call as an +// OpVerify event whose outcome distinguishes a rejected signature from a successful one. +func (v *instrumentedVerifier) Verify(message, sigma []byte) error { + t := Start(v.observer, OpVerify, v.principal, v.role) + err := v.verifier.Verify(message, sigma) + t.DoneVerify(context.Background(), err) + + return err +} diff --git a/token/services/identity/sigobserve/decorator_test.go b/token/services/identity/sigobserve/decorator_test.go new file mode 100644 index 0000000000..f7e3c271e2 --- /dev/null +++ b/token/services/identity/sigobserve/decorator_test.go @@ -0,0 +1,131 @@ +/* +Copyright IBM Corp. All Rights Reserved. + +SPDX-License-Identifier: Apache-2.0 +*/ + +package sigobserve_test + +import ( + "testing" + + "github.com/LFDT-Panurus/panurus/token/driver" + dmock "github.com/LFDT-Panurus/panurus/token/driver/mock" + "github.com/LFDT-Panurus/panurus/token/services/identity/sigobserve" + "github.com/hyperledger-labs/fabric-smart-client/pkg/utils/errors" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +// signingIdentity is a driver.Signer that also serializes, i.e. a driver.SigningIdentity. +type signingIdentity struct { + *dmock.Signer + serialized []byte +} + +func (s *signingIdentity) Serialize() ([]byte, error) { return s.serialized, nil } + +func TestInstrumentSignerReturnsTheSignerUnwrapped(t *testing.T) { + signer := &dmock.Signer{} + + assert.Same(t, signer, sigobserve.InstrumentSigner(signer, nil, "hash", sigobserve.RoleOwner)) + assert.Same(t, signer, sigobserve.InstrumentSigner(signer, sigobserve.Nop, "hash", sigobserve.RoleOwner)) + assert.Nil(t, sigobserve.InstrumentSigner(nil, &recorder{}, "hash", sigobserve.RoleOwner)) +} + +func TestInstrumentSignerReportsSign(t *testing.T) { + t.Run("success", func(t *testing.T) { + r := &recorder{} + signer := &dmock.Signer{} + signer.SignReturns([]byte("sigma"), nil) + + wrapped := sigobserve.InstrumentSigner(signer, r, "hash", sigobserve.RoleOwner) + sigma, err := wrapped.Sign([]byte("message")) + require.NoError(t, err) + assert.Equal(t, []byte("sigma"), sigma, "the wrapper must be transparent") + assert.Equal(t, []byte("message"), signer.SignArgsForCall(0)) + + e := r.one(t) + assert.Equal(t, sigobserve.OpSign, e.Op) + assert.Equal(t, "hash", e.Principal) + assert.Equal(t, sigobserve.RoleOwner, e.Role) + assert.Equal(t, sigobserve.OutcomeOK, e.Outcome) + }) + + t.Run("failure", func(t *testing.T) { + r := &recorder{} + signer := &dmock.Signer{} + expected := errors.New("no key") + signer.SignReturns(nil, expected) + + wrapped := sigobserve.InstrumentSigner(signer, r, "hash", sigobserve.RoleIssuer) + _, err := wrapped.Sign([]byte("message")) + require.ErrorIs(t, err, expected) + + e := r.one(t) + assert.Equal(t, sigobserve.OutcomeError, e.Outcome) + assert.Equal(t, expected, e.Err) + }) +} + +// TestInstrumentSignerPreservesSigningIdentity pins the behaviour callers depend on: wrapping a +// signer must not hide its Serialize method, or every wallet that resolves a signing identity +// through the provider would break. +func TestInstrumentSignerPreservesSigningIdentity(t *testing.T) { + r := &recorder{} + signer := &signingIdentity{Signer: &dmock.Signer{}, serialized: []byte("raw-identity")} + signer.SignReturns([]byte("sigma"), nil) + + wrapped := sigobserve.InstrumentSigner(signer, r, "hash", sigobserve.RoleOwner) + si, ok := wrapped.(driver.SigningIdentity) + require.True(t, ok, "a wrapped SigningIdentity must remain a SigningIdentity") + + raw, err := si.Serialize() + require.NoError(t, err) + assert.Equal(t, []byte("raw-identity"), raw) + + _, err = si.Sign([]byte("message")) + require.NoError(t, err) + assert.Equal(t, sigobserve.OpSign, r.one(t).Op, "Serialize is not instrumented, Sign is") +} + +func TestInstrumentVerifierReturnsTheVerifierUnwrapped(t *testing.T) { + verifier := &dmock.Verifier{} + + assert.Same(t, verifier, sigobserve.InstrumentVerifier(verifier, nil, "hash", sigobserve.RoleOwner)) + assert.Same(t, verifier, sigobserve.InstrumentVerifier(verifier, sigobserve.Nop, "hash", sigobserve.RoleOwner)) + assert.Nil(t, sigobserve.InstrumentVerifier(nil, &recorder{}, "hash", sigobserve.RoleOwner)) +} + +func TestInstrumentVerifierReportsVerify(t *testing.T) { + t.Run("accepted signature", func(t *testing.T) { + r := &recorder{} + verifier := &dmock.Verifier{} + verifier.VerifyReturns(nil) + + wrapped := sigobserve.InstrumentVerifier(verifier, r, "hash", sigobserve.RoleAuditor) + require.NoError(t, wrapped.Verify([]byte("message"), []byte("sigma"))) + + message, sigma := verifier.VerifyArgsForCall(0) + assert.Equal(t, []byte("message"), message) + assert.Equal(t, []byte("sigma"), sigma) + + e := r.one(t) + assert.Equal(t, sigobserve.OpVerify, e.Op) + assert.Equal(t, sigobserve.RoleAuditor, e.Role) + assert.Equal(t, sigobserve.OutcomeOK, e.Outcome) + }) + + t.Run("rejected signature", func(t *testing.T) { + r := &recorder{} + verifier := &dmock.Verifier{} + expected := errors.New("invalid signature") + verifier.VerifyReturns(expected) + + wrapped := sigobserve.InstrumentVerifier(verifier, r, "hash", sigobserve.RoleOwner) + require.ErrorIs(t, wrapped.Verify([]byte("message"), []byte("sigma")), expected) + + e := r.one(t) + assert.Equal(t, sigobserve.OutcomeInvalid, e.Outcome, "a rejected signature is the signal to watch") + }) +} diff --git a/token/services/identity/sigobserve/observe.go b/token/services/identity/sigobserve/observe.go new file mode 100644 index 0000000000..7199cca3d9 --- /dev/null +++ b/token/services/identity/sigobserve/observe.go @@ -0,0 +1,271 @@ +/* +Copyright IBM Corp. All Rights Reserved. + +SPDX-License-Identifier: Apache-2.0 +*/ + +// Package sigobserve carries the event vocabulary of the Signer and Verifier services: one +// Event per completed operation, and an Observer that consumes them. +// +// The package deliberately depends on nothing but the driver types. Metrics, audit logging +// and throttle escalation are all Observers living in their own packages, so instrumenting a +// call site never drags a metrics provider or a policy engine into it, and package token can +// import this vocabulary without an import cycle. +// +// Observers run inline on the signing and verification hot paths. Implementations must be +// safe for concurrent use and must not block. +package sigobserve + +import ( + "context" + "time" +) + +// Op identifies an instrumented Signer or Verifier service operation. +type Op string + +const ( + // OpGetSigner is a signer resolution (identity.Provider.GetSigner). + OpGetSigner Op = "get_signer" + // OpRegisterSigner is the registration of a signer/verifier pair for an identity. + OpRegisterSigner Op = "register_signer" + // OpRegisterIdentityDescriptor is the registration of a full identity descriptor. + OpRegisterIdentityDescriptor Op = "register_identity_descriptor" + // OpIsMe is an "is this identity mine" lookup (IsMe/AreMe). + OpIsMe Op = "is_me" + // OpGetAuditInfo is an audit-info lookup for an identity. + OpGetAuditInfo Op = "get_audit_info" + // OpBind is the binding of ephemeral identities to a long-term one. + OpBind Op = "bind" + // OpOwnerVerifier is the resolution of an owner's verifier. + OpOwnerVerifier Op = "owner_verifier" + // OpIssuerVerifier is the resolution of an issuer's verifier. + OpIssuerVerifier Op = "issuer_verifier" + // OpAuditorVerifier is the resolution of an auditor's verifier. + OpAuditorVerifier Op = "auditor_verifier" + // OpSign is an invocation of a resolved signer. + OpSign Op = "sign" + // OpVerify is an invocation of a resolved verifier. + OpVerify Op = "verify" + // OpEscalation is a change of a principal's throttle level. It reports policy state, not + // a service call, so it carries no duration. + OpEscalation Op = "escalation" +) + +// Role is the role an identity plays in a token transaction, when the instrumented +// operation is specific to one. +type Role string + +const ( + // RoleOwner is a token owner. + RoleOwner Role = "owner" + // RoleIssuer is a token issuer. + RoleIssuer Role = "issuer" + // RoleAuditor is an auditor. + RoleAuditor Role = "auditor" + // RoleUnknown is used for operations that are not tied to a single role. + RoleUnknown Role = "unknown" +) + +// Outcome is how an instrumented operation ended. +type Outcome string + +const ( + // OutcomeOK is a successful operation. + OutcomeOK Outcome = "ok" + // OutcomeError is an operation that failed for reasons other than an invalid signature: + // a missing signer, a storage error, a malformed identity. + OutcomeError Outcome = "error" + // OutcomeInvalid is a verification that did not succeed. It does not separate a forged + // signature from a malformed input - a Verifier reports both as a plain error - which is + // exactly why it is the signal to watch: a principal driving this counter up is either + // broken or probing. + OutcomeInvalid Outcome = "invalid" + // OutcomeThrottled is an operation denied by policy before it ran. + OutcomeThrottled Outcome = "throttled" +) + +// Resolution paths reported by signer resolution, describing how the signer was obtained. +const ( + // PathCache is a hit in the signer cache. + PathCache = "cache" + // PathRouted is a conf_id-pinned SignerRouter hit. + PathRouted = "routed" + // PathFallback is the linear-scan probing deserializer. + PathFallback = "fallback" +) + +// Event describes one completed Signer or Verifier service operation. +type Event struct { + // Op is the operation performed. + Op Op + // Principal identifies the identity the operation was performed for. It is an identity + // hash (driver.Identity.UniqueID()), never raw identity bytes: it is stable, it is + // already the signer cache key, and it keeps identity material out of logs. + Principal string + // Role is the identity's role, or RoleUnknown when the operation spans roles. + Role Role + // Outcome is how the operation ended. + Outcome Outcome + // Path reports how a signer resolution was satisfied (PathCache, PathRouted, + // PathFallback). It is empty for operations that resolve nothing. + Path string + // CacheChecked reports whether this operation consulted the signer cache, and hence + // whether CacheHit carries a meaning. + CacheChecked bool + // CacheHit reports whether the consulted cache had the entry. + CacheHit bool + // Duration is the wall-clock time the operation took. It is zero for OpEscalation. + Duration time.Duration + // Level is the throttle level a principal moved to, for OpEscalation events. + Level string + // Reason explains an OpEscalation event ("rate", "error_rate", "invalid_signature_rate", + // "quiet_period"). + Reason string + // Err is the error the operation failed with, if any. + Err error +} + +// Observer consumes operation events. +type Observer interface { + // Observe records a completed operation. It must not block, must tolerate being called + // concurrently, and must not retain the Event's Err beyond the call. + Observe(ctx context.Context, e Event) +} + +// Gate decides whether an operation on behalf of a principal may proceed. It is declared here, +// next to the event vocabulary, so that a policy implementation and the client-facing service +// that consults it can agree on the contract without depending on each other. +// +// Implementations must be safe for concurrent use and must not block. +type Gate interface { + // Allow reports whether op on behalf of principal (an identity hash) may proceed, + // returning nil when it may. + Allow(ctx context.Context, principal string, op Op) error +} + +// ObserverFunc adapts a function to the Observer interface. +type ObserverFunc func(ctx context.Context, e Event) + +// Observe calls f. +func (f ObserverFunc) Observe(ctx context.Context, e Event) { f(ctx, e) } + +// nopObserver drops every event. +type nopObserver struct{} + +// Observe does nothing. +func (nopObserver) Observe(context.Context, Event) {} + +// Nop is an Observer that drops every event. It is what a caller with no instrumentation +// configured should use, so call sites never have to nil-check. +var Nop Observer = nopObserver{} + +// multiObserver fans an event out to several observers. +type multiObserver []Observer + +// Observe forwards e to every observer in order. +func (m multiObserver) Observe(ctx context.Context, e Event) { + for _, o := range m { + o.Observe(ctx, e) + } +} + +// Multi returns an Observer that forwards every event to all of the passed observers, in +// order. Nil observers are dropped; the result of Multi with no effective observer is Nop, +// and with exactly one it is that observer itself, so the common cases cost no extra +// indirection. +func Multi(observers ...Observer) Observer { + effective := make([]Observer, 0, len(observers)) + for _, o := range observers { + if o == nil || o == Nop { + continue + } + effective = append(effective, o) + } + + switch len(effective) { + case 0: + return Nop + case 1: + return effective[0] + default: + return multiObserver(effective) + } +} + +// Timer measures one operation and reports it to an Observer when it ends. It is a value +// type holding no heap state, so instrumenting a hot path with it allocates nothing. +// +// Typical use: +// +// t := sigobserve.Start(o, sigobserve.OpSign, principal, role) +// sigma, err := signer.Sign(message) +// t.Done(ctx, err) +type Timer struct { + observer Observer + op Op + principal string + role Role + start time.Time +} + +// Start begins measuring an operation. A nil observer is treated as Nop. +func Start(o Observer, op Op, principal string, role Role) Timer { + if o == nil { + o = Nop + } + + return Timer{observer: o, op: op, principal: principal, role: role, start: time.Now()} +} + +// Done reports the operation as OutcomeOK when err is nil and OutcomeError otherwise. +func (t Timer) Done(ctx context.Context, err error) { + t.emit(ctx, Event{Outcome: outcomeOf(err), Err: err}) +} + +// DoneVerify reports a verification, mapping a non-nil err to OutcomeInvalid rather than +// OutcomeError: a Verifier that returns an error has rejected the signature, and that +// rejection is the security signal callers watch. +func (t Timer) DoneVerify(ctx context.Context, err error) { + outcome := OutcomeOK + if err != nil { + outcome = OutcomeInvalid + } + t.emit(ctx, Event{Outcome: outcome, Err: err}) +} + +// DoneThrottled reports the operation as denied by policy, with the error returned to the +// caller. +func (t Timer) DoneThrottled(ctx context.Context, err error) { + t.emit(ctx, Event{Outcome: OutcomeThrottled, Err: err}) +} + +// DoneResolution reports a signer resolution, adding the path it took and whether the cache +// was consulted and hit. +func (t Timer) DoneResolution(ctx context.Context, path string, err error) { + t.emit(ctx, Event{ + Outcome: outcomeOf(err), + Path: path, + CacheChecked: true, + CacheHit: err == nil && path == PathCache, + Err: err, + }) +} + +// emit fills in the fields the Timer owns and hands the event to the observer. +func (t Timer) emit(ctx context.Context, e Event) { + e.Op = t.op + e.Principal = t.principal + e.Role = t.role + e.Duration = time.Since(t.start) + t.observer.Observe(ctx, e) +} + +// outcomeOf maps an error to the outcome of a non-verification operation. +func outcomeOf(err error) Outcome { + if err != nil { + return OutcomeError + } + + return OutcomeOK +} diff --git a/token/services/identity/sigobserve/observe_test.go b/token/services/identity/sigobserve/observe_test.go new file mode 100644 index 0000000000..547deeab8e --- /dev/null +++ b/token/services/identity/sigobserve/observe_test.go @@ -0,0 +1,172 @@ +/* +Copyright IBM Corp. All Rights Reserved. + +SPDX-License-Identifier: Apache-2.0 +*/ + +package sigobserve_test + +import ( + "context" + "sync" + "testing" + + "github.com/LFDT-Panurus/panurus/token/services/identity/sigobserve" + "github.com/hyperledger-labs/fabric-smart-client/pkg/utils/errors" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +// recorder is an Observer that keeps every event it is handed. +type recorder struct { + mu sync.Mutex + events []sigobserve.Event +} + +func (r *recorder) Observe(_ context.Context, e sigobserve.Event) { + r.mu.Lock() + defer r.mu.Unlock() + r.events = append(r.events, e) +} + +func (r *recorder) all() []sigobserve.Event { + r.mu.Lock() + defer r.mu.Unlock() + + return append([]sigobserve.Event(nil), r.events...) +} + +func (r *recorder) one(t *testing.T) sigobserve.Event { + t.Helper() + events := r.all() + require.Len(t, events, 1) + + return events[0] +} + +func TestNopDropsEvents(t *testing.T) { + // The contract is only that it does not panic and reports nothing: there is nothing to + // observe about a dropped event. + sigobserve.Nop.Observe(t.Context(), sigobserve.Event{Op: sigobserve.OpSign}) +} + +func TestObserverFunc(t *testing.T) { + var got sigobserve.Event + var f sigobserve.Observer = sigobserve.ObserverFunc(func(_ context.Context, e sigobserve.Event) { got = e }) + + f.Observe(t.Context(), sigobserve.Event{Op: sigobserve.OpVerify, Principal: "hash"}) + assert.Equal(t, sigobserve.OpVerify, got.Op) + assert.Equal(t, "hash", got.Principal) +} + +func TestMulti(t *testing.T) { + t.Run("no effective observer collapses to Nop", func(t *testing.T) { + assert.Equal(t, sigobserve.Nop, sigobserve.Multi()) + assert.Equal(t, sigobserve.Nop, sigobserve.Multi(nil, nil)) + assert.Equal(t, sigobserve.Nop, sigobserve.Multi(nil, sigobserve.Nop)) + }) + + t.Run("a single effective observer is returned unwrapped", func(t *testing.T) { + r := &recorder{} + assert.Same(t, r, sigobserve.Multi(nil, r, sigobserve.Nop)) + }) + + t.Run("fans out in order", func(t *testing.T) { + var order []string + first := sigobserve.ObserverFunc(func(context.Context, sigobserve.Event) { order = append(order, "first") }) + second := sigobserve.ObserverFunc(func(context.Context, sigobserve.Event) { order = append(order, "second") }) + + sigobserve.Multi(first, nil, second).Observe(t.Context(), sigobserve.Event{}) + assert.Equal(t, []string{"first", "second"}, order) + }) +} + +func TestTimerDone(t *testing.T) { + t.Run("success", func(t *testing.T) { + r := &recorder{} + sigobserve.Start(r, sigobserve.OpGetSigner, "hash", sigobserve.RoleOwner).Done(t.Context(), nil) + + e := r.one(t) + assert.Equal(t, sigobserve.OpGetSigner, e.Op) + assert.Equal(t, "hash", e.Principal) + assert.Equal(t, sigobserve.RoleOwner, e.Role) + assert.Equal(t, sigobserve.OutcomeOK, e.Outcome) + require.NoError(t, e.Err) + assert.Positive(t, e.Duration) + }) + + t.Run("failure", func(t *testing.T) { + r := &recorder{} + expected := errors.New("boom") + sigobserve.Start(r, sigobserve.OpBind, "hash", sigobserve.RoleUnknown).Done(t.Context(), expected) + + e := r.one(t) + assert.Equal(t, sigobserve.OutcomeError, e.Outcome) + assert.Equal(t, expected, e.Err) + }) +} + +func TestTimerDoneVerifyMapsErrorsToInvalid(t *testing.T) { + r := &recorder{} + expected := errors.New("signature mismatch") + sigobserve.Start(r, sigobserve.OpVerify, "hash", sigobserve.RoleIssuer).DoneVerify(t.Context(), expected) + sigobserve.Start(r, sigobserve.OpVerify, "hash", sigobserve.RoleIssuer).DoneVerify(t.Context(), nil) + + events := r.all() + require.Len(t, events, 2) + assert.Equal(t, sigobserve.OutcomeInvalid, events[0].Outcome, "a rejected signature is invalid, not an error") + assert.Equal(t, expected, events[0].Err) + assert.Equal(t, sigobserve.OutcomeOK, events[1].Outcome) +} + +func TestTimerDoneThrottled(t *testing.T) { + r := &recorder{} + expected := errors.New("denied") + sigobserve.Start(r, sigobserve.OpOwnerVerifier, "hash", sigobserve.RoleOwner).DoneThrottled(t.Context(), expected) + + e := r.one(t) + assert.Equal(t, sigobserve.OutcomeThrottled, e.Outcome) + assert.Equal(t, expected, e.Err) +} + +func TestTimerDoneResolution(t *testing.T) { + tests := []struct { + name string + path string + err error + outcome sigobserve.Outcome + cacheHit bool + }{ + {name: "cache hit", path: sigobserve.PathCache, outcome: sigobserve.OutcomeOK, cacheHit: true}, + {name: "routed", path: sigobserve.PathRouted, outcome: sigobserve.OutcomeOK}, + {name: "fallback", path: sigobserve.PathFallback, outcome: sigobserve.OutcomeOK}, + {name: "failed", path: sigobserve.PathFallback, err: errors.New("no signer"), outcome: sigobserve.OutcomeError}, + } + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + r := &recorder{} + sigobserve.Start(r, sigobserve.OpGetSigner, "hash", sigobserve.RoleUnknown). + DoneResolution(t.Context(), test.path, test.err) + + e := r.one(t) + assert.Equal(t, test.path, e.Path) + assert.Equal(t, test.outcome, e.Outcome) + assert.True(t, e.CacheChecked, "a resolution always consults the cache") + assert.Equal(t, test.cacheHit, e.CacheHit) + }) + } +} + +func TestStartToleratesANilObserver(t *testing.T) { + sigobserve.Start(nil, sigobserve.OpSign, "hash", sigobserve.RoleUnknown).Done(t.Context(), nil) +} + +// TestTimerAllocatesNothing guards the claim that instrumenting a hot path with a Timer is free +// when the observer drops the event: a regression here would put an allocation on every Sign. +func TestTimerAllocatesNothing(t *testing.T) { + ctx := t.Context() + allocs := testing.AllocsPerRun(100, func() { + sigobserve.Start(sigobserve.Nop, sigobserve.OpSign, "hash", sigobserve.RoleUnknown).Done(ctx, nil) + }) + assert.InDelta(t, 0.0, allocs, 0, "a Timer reporting to Nop should not allocate") +} diff --git a/token/services/identity/sigpolicy/stack.go b/token/services/identity/sigpolicy/stack.go new file mode 100644 index 0000000000..e12caa04c8 --- /dev/null +++ b/token/services/identity/sigpolicy/stack.go @@ -0,0 +1,143 @@ +/* +Copyright IBM Corp. All Rights Reserved. + +SPDX-License-Identifier: Apache-2.0 +*/ + +// Package sigpolicy assembles the signature observability stack a driver installs on a TMS: +// metrics, the audit log, and the throttle policy that both feeds on them and gates the +// client-facing signature service. +// +// It exists so that the wiring lives in one place instead of being duplicated, and drifting, +// across every token driver. A driver calls New once and hands the resulting Stack to the +// identity provider, the deserializer and the token service. +package sigpolicy + +import ( + "github.com/LFDT-Panurus/panurus/token/services/identity/sigobserve" + "github.com/LFDT-Panurus/panurus/token/services/identity/throttle" + "github.com/LFDT-Panurus/panurus/token/services/logging" + "github.com/hyperledger-labs/fabric-smart-client/pkg/utils/errors" +) + +// ConfigService is the subset of the TMS configuration the stack reads. +type ConfigService interface { + // UnmarshalKey decodes the configuration under key into rawVal. + UnmarshalKey(key string, rawVal any) error +} + +// Reporter is the metrics sink of the stack: an observer of every operation, and the gauge the +// throttle policy reports its own state to. identity.Metrics implements it. +type Reporter interface { + sigobserve.Observer + throttle.LevelGauge +} + +// Stack is an assembled signature observability and policy bundle. +// +// Its Observer is what every instrumented call site reports to; its Gate is what the +// client-facing signature service consults. Gate is nil when the policy is disabled, which is +// what keeps an unthrottled deployment from paying for attribution it never uses. +type Stack struct { + observer sigobserve.Observer + gate sigobserve.Gate + escalator *throttle.Escalator + config *throttle.Config +} + +// New assembles the stack for one TMS from cfg. logger receives the audit trail and reporter the +// metrics; either may be nil, in which case that sink is simply absent. +// +// The escalator observes the same events the metrics and the audit log do, but it reports its own +// escalations only to those two - never back to itself - so the reporting chain cannot loop. +func New(logger logging.Logger, cs ConfigService, reporter Reporter) (*Stack, error) { + cfg, err := readConfig(cs) + if err != nil { + return nil, err + } + + var ( + metricsObserver sigobserve.Observer + gauge throttle.LevelGauge + ) + if reporter != nil { + metricsObserver = reporter + gauge = reporter + } + + var auditObserver sigobserve.Observer + if logger != nil { + auditObserver = sigobserve.NewAuditLogger(logger) + } + + reporting := sigobserve.Multi(metricsObserver, auditObserver) + escalator := throttle.New(cfg, throttle.WithObserver(reporting), throttle.WithLevelGauge(gauge)) + + observers := []sigobserve.Observer{metricsObserver, auditObserver} + if cfg.Enabled() { + observers = append(observers, escalator) + } + + s := &Stack{ + observer: sigobserve.Multi(observers...), + escalator: escalator, + config: cfg, + } + if cfg.Enabled() { + s.gate = escalator + } + + return s, nil +} + +// Observer returns the observer every instrumented signature call site reports to. +func (s *Stack) Observer() sigobserve.Observer { + if s == nil { + return sigobserve.Nop + } + + return s.observer +} + +// Gate returns the gate the client-facing signature service consults, or nil when the throttle +// policy is disabled. +func (s *Stack) Gate() sigobserve.Gate { + if s == nil { + return nil + } + + return s.gate +} + +// Config returns the throttle configuration the stack was assembled with. +func (s *Stack) Config() *throttle.Config { + if s == nil { + return nil + } + + return s.config +} + +// Stop releases the resources held by the stack. It is idempotent. +func (s *Stack) Stop() { + if s == nil || s.escalator == nil { + return + } + + s.escalator.Stop() +} + +// readConfig reads the throttle configuration, tolerating the absence of a configuration service +// so that a driver built without one (a wallet-only service, for instance) still gets defaults. +func readConfig(cs ConfigService) (*throttle.Config, error) { + if cs == nil { + cfg := &throttle.Config{} + if err := cfg.Defaults(); err != nil { + return nil, errors.Wrapf(err, "failed defaulting throttle configuration") + } + + return cfg, nil + } + + return throttle.NewConfig(cs) +} diff --git a/token/services/identity/sigpolicy/stack_test.go b/token/services/identity/sigpolicy/stack_test.go new file mode 100644 index 0000000000..c5e70ceb13 --- /dev/null +++ b/token/services/identity/sigpolicy/stack_test.go @@ -0,0 +1,258 @@ +/* +Copyright IBM Corp. All Rights Reserved. + +SPDX-License-Identifier: Apache-2.0 +*/ + +package sigpolicy_test + +import ( + "context" + "sync" + "testing" + "time" + + "github.com/LFDT-Panurus/panurus/token" + "github.com/LFDT-Panurus/panurus/token/services/identity/sigobserve" + "github.com/LFDT-Panurus/panurus/token/services/identity/sigpolicy" + "github.com/LFDT-Panurus/panurus/token/services/identity/throttle" + "github.com/LFDT-Panurus/panurus/token/services/logging" + "github.com/hyperledger-labs/fabric-smart-client/pkg/utils/errors" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +const alice = "alice-hash" + +// fakeConfigService serves one prepared throttle configuration, or an error. +type fakeConfigService struct { + config *throttle.Config + err error +} + +func (c *fakeConfigService) UnmarshalKey(_ string, rawVal any) error { + if c.err != nil { + return c.err + } + if c.config == nil { + return nil + } + target, ok := rawVal.(*throttle.Config) + if !ok { + return errors.Errorf("unexpected target type [%T]", rawVal) + } + *target = *c.config + + return nil +} + +// fakeReporter is the metrics sink of the stack: it records both the events it observes and the +// level counts the policy reports to it. +type fakeReporter struct { + mu sync.Mutex + events []sigobserve.Event + counts map[string]int +} + +func newFakeReporter() *fakeReporter { return &fakeReporter{counts: map[string]int{}} } + +func (r *fakeReporter) Observe(_ context.Context, e sigobserve.Event) { + r.mu.Lock() + defer r.mu.Unlock() + r.events = append(r.events, e) +} + +func (r *fakeReporter) SetThrottledPrincipals(level string, n int) { + r.mu.Lock() + defer r.mu.Unlock() + r.counts[level] = n +} + +func (r *fakeReporter) all() []sigobserve.Event { + r.mu.Lock() + defer r.mu.Unlock() + + return append([]sigobserve.Event(nil), r.events...) +} + +func (r *fakeReporter) count(level string) int { + r.mu.Lock() + defer r.mu.Unlock() + + return r.counts[level] +} + +// enforcing returns a configuration that denies after a single request. +func enforcing() *throttle.Config { + return &throttle.Config{ + Mode: throttle.ModeEnforce, + Rate: 1, + Burst: 1, + MinSamples: 2, + SoftDuration: time.Minute, + BlockDuration: time.Minute, + DeescalateAfter: 2 * time.Minute, + } +} + +func newStack(t *testing.T, cfg *throttle.Config, reporter sigpolicy.Reporter) *sigpolicy.Stack { + t.Helper() + + s, err := sigpolicy.New(logging.MustGetLogger(), &fakeConfigService{config: cfg}, reporter) + require.NoError(t, err) + t.Cleanup(s.Stop) + + return s +} + +// TestNewStackDefaults covers the shape a driver gets when the deployment says nothing: the +// default mode observes without denying, so the gate exists but never refuses. +func TestNewStackDefaults(t *testing.T) { + reporter := newFakeReporter() + s := newStack(t, nil, reporter) + + require.NotNil(t, s.Config()) + assert.Equal(t, throttle.DefaultMode, s.Config().Mode) + assert.NotNil(t, s.Observer()) + require.NotNil(t, s.Gate(), "the policy observes by default, so it needs the attribution the gate provides") + + for range 100 { + require.NoError(t, s.Gate().Allow(t.Context(), alice, sigobserve.OpGetSigner), + "the default policy must not deny, since that would change a running deployment") + } +} + +func TestNewStackWithoutAConfigService(t *testing.T) { + s, err := sigpolicy.New(logging.MustGetLogger(), nil, newFakeReporter()) + require.NoError(t, err) + t.Cleanup(s.Stop) + + require.NotNil(t, s.Config(), "a driver built without configuration still gets the defaults") + assert.Equal(t, throttle.DefaultMode, s.Config().Mode) + assert.NotNil(t, s.Gate()) +} + +// TestNewStackDisabledHasNoGate pins what "off" buys: with no gate the signature service skips +// hashing identities for attribution it would never use. +func TestNewStackDisabledHasNoGate(t *testing.T) { + s := newStack(t, &throttle.Config{Mode: throttle.ModeOff}, newFakeReporter()) + + assert.Nil(t, s.Gate()) + assert.NotNil(t, s.Observer(), "instrumentation stays available even with the policy off") +} + +// TestNewStackDisabledWithoutSinksCostsNothing pins the other half of "off": with the policy +// disabled and neither metrics nor a logger configured, the escalator has nothing left to feed +// and the observer collapses to Nop, so InstrumentSigner/InstrumentVerifier skip wrapping +// entirely and the signing path pays nothing for a feature that is switched off. +func TestNewStackDisabledWithoutSinksCostsNothing(t *testing.T) { + s, err := sigpolicy.New(nil, &fakeConfigService{config: &throttle.Config{Mode: throttle.ModeOff}}, nil) + require.NoError(t, err) + t.Cleanup(s.Stop) + + assert.Nil(t, s.Gate()) + assert.Equal(t, sigobserve.Nop, s.Observer(), "off with no sinks must collapse to Nop, not merely a functioning escalator") +} + +func TestNewStackConfigError(t *testing.T) { + _, err := sigpolicy.New(logging.MustGetLogger(), &fakeConfigService{err: errors.New("bad yaml")}, newFakeReporter()) + require.ErrorContains(t, err, "failed unmarshalling [identity.throttle]") +} + +func TestNewStackRejectsAnInvalidConfiguration(t *testing.T) { + _, err := sigpolicy.New(logging.MustGetLogger(), &fakeConfigService{config: &throttle.Config{Mode: throttle.Mode("paranoid")}}, newFakeReporter()) + require.ErrorContains(t, err, "invalid throttle mode [paranoid]") +} + +// TestStackObserverFeedsTheReporterAndThePolicy is the assembly this package exists for: one +// observer that both records an operation and lets it count towards the principal's throttle +// state. +func TestStackObserverFeedsTheReporterAndThePolicy(t *testing.T) { + cfg := enforcing() + cfg.Rate, cfg.Burst = 1000, 1000 + cfg.MinSamples = 2 + cfg.InvalidSignatureRateThreshold = 0.5 + reporter := newFakeReporter() + s := newStack(t, cfg, reporter) + + for range 2 { + s.Observer().Observe(t.Context(), sigobserve.Event{ + Op: sigobserve.OpVerify, + Principal: alice, + Outcome: sigobserve.OutcomeInvalid, + }) + } + + events := reporter.all() + require.Len(t, events, 3, "two verifications, plus the escalation they caused") + assert.Equal(t, sigobserve.OpVerify, events[0].Op) + assert.Equal(t, sigobserve.OpEscalation, events[2].Op) + assert.Equal(t, string(throttle.LevelSoft), events[2].Level) + assert.Equal(t, throttle.ReasonInvalidSignatureRate, events[2].Reason) + assert.Equal(t, 1, reporter.count(string(throttle.LevelSoft)), "the gauge is wired to the same reporter") +} + +// TestStackEscalationsDoNotLoop guards the one wiring mistake this assembly can make: the +// escalator observes the stack's events, so if its own escalations went back through the stack +// observer instead of straight to the reporting chain, one escalation would feed the next. +func TestStackEscalationsDoNotLoop(t *testing.T) { + cfg := enforcing() + cfg.Rate, cfg.Burst = 1000, 1000 + cfg.MinSamples = 1 + cfg.InvalidSignatureRateThreshold = 0.1 + reporter := newFakeReporter() + s := newStack(t, cfg, reporter) + + s.Observer().Observe(t.Context(), sigobserve.Event{ + Op: sigobserve.OpVerify, + Principal: alice, + Outcome: sigobserve.OutcomeInvalid, + }) + + escalations := 0 + for _, e := range reporter.all() { + if e.Op == sigobserve.OpEscalation { + escalations++ + } + } + assert.Equal(t, 1, escalations, "one violation must produce exactly one escalation") +} + +func TestStackGateEnforces(t *testing.T) { + s := newStack(t, enforcing(), newFakeReporter()) + + require.NoError(t, s.Gate().Allow(t.Context(), alice, sigobserve.OpGetSigner)) + require.ErrorIs(t, s.Gate().Allow(t.Context(), alice, sigobserve.OpGetSigner), token.SignatureThrottled) +} + +// TestNewStackWithoutSinks covers a driver that has neither metrics nor a logger to give: the +// policy still works, it just reports to nobody. +func TestNewStackWithoutSinks(t *testing.T) { + s, err := sigpolicy.New(nil, &fakeConfigService{config: enforcing()}, nil) + require.NoError(t, err) + t.Cleanup(s.Stop) + + s.Observer().Observe(t.Context(), sigobserve.Event{Op: sigobserve.OpVerify, Principal: alice, Outcome: sigobserve.OutcomeInvalid}) + require.NoError(t, s.Gate().Allow(t.Context(), alice, sigobserve.OpGetSigner)) + require.ErrorIs(t, s.Gate().Allow(t.Context(), alice, sigobserve.OpGetSigner), token.SignatureThrottled, + "the policy must enforce whether or not anyone is listening") +} + +func TestStackStopIsIdempotent(t *testing.T) { + s := newStack(t, enforcing(), newFakeReporter()) + + s.Stop() + s.Stop() +} + +// TestNilStackIsUsable covers the zero value a caller may hold before, or instead of, assembling +// a stack: every accessor answers without a nil check at the call site. +func TestNilStackIsUsable(t *testing.T) { + var s *sigpolicy.Stack + + assert.Equal(t, sigobserve.Nop, s.Observer()) + assert.Nil(t, s.Gate()) + assert.Nil(t, s.Config()) + s.Stop() + s.Observer().Observe(t.Context(), sigobserve.Event{Op: sigobserve.OpSign}) +} diff --git a/token/services/identity/throttle/config.go b/token/services/identity/throttle/config.go new file mode 100644 index 0000000000..3af96bba18 --- /dev/null +++ b/token/services/identity/throttle/config.go @@ -0,0 +1,205 @@ +/* +Copyright IBM Corp. All Rights Reserved. + +SPDX-License-Identifier: Apache-2.0 +*/ + +package throttle + +import ( + "time" + + "github.com/hyperledger-labs/fabric-smart-client/pkg/utils/errors" +) + +// Mode selects how much of the throttle policy is active. +type Mode string + +const ( + // ModeOff disables the policy entirely: nothing is metered and nothing is denied. + ModeOff Mode = "off" + // ModeMonitor evaluates the policy and reports every escalation through metrics and the + // audit log, but never denies an operation. It is how an operator tunes thresholds + // against real traffic before enforcing them. + ModeMonitor Mode = "monitor" + // ModeEnforce evaluates the policy and denies operations from principals that are + // currently throttled. + ModeEnforce Mode = "enforce" +) + +// Defaults for the throttle policy. They are deliberately generous: the policy is a safety +// net against a runaway or hostile caller, not a throughput cap on healthy traffic. +const ( + // DefaultMode is the mode used when none is configured. Escalation is evaluated and + // reported but not enforced, because automatically blocking a principal changes the + // behaviour of a running deployment and that has to be a deliberate decision. + DefaultMode = ModeMonitor + // DefaultRate is the number of metered signature operations per second a single principal + // may perform. + DefaultRate = 200 + // DefaultBurst is the bucket capacity, absorbing short spikes without raising the + // sustained rate. + DefaultBurst = 400 + // DefaultWindow is the period over which error and invalid-signature ratios are + // evaluated. + DefaultWindow = time.Minute + // DefaultMinSamples is the smallest number of observations in a window that can support + // a ratio-based decision. Below it, ratios are noise: one failure out of three calls is + // not an attack. + DefaultMinSamples = 50 + // DefaultErrorRateThreshold is the fraction of failing operations in a window that + // escalates a principal. + DefaultErrorRateThreshold = 0.5 + // DefaultInvalidSignatureRateThreshold is the fraction of rejected verifications in a + // window that escalates a principal. It is stricter than the error threshold: a healthy + // caller does not present bad signatures. + DefaultInvalidSignatureRateThreshold = 0.2 + // DefaultQuotaReductionFactor is the multiplier applied to a principal's rate when it is + // first escalated. + DefaultQuotaReductionFactor = 0.25 + // DefaultSoftDuration is the minimum time a principal stays on a reduced quota. + DefaultSoftDuration = 5 * time.Minute + // DefaultBlockDuration is how long a blocked principal is refused before being released + // back to a reduced quota. + DefaultBlockDuration = time.Minute + // DefaultDeescalateAfter is how long a principal must go without a violation before its + // full quota is restored. + DefaultDeescalateAfter = 5 * time.Minute + // DefaultIdleTTL is how long per-principal state is kept after the last operation. + DefaultIdleTTL = 10 * time.Minute +) + +// configService is the subset of the TMS configuration the policy reads. +type configService interface { + // UnmarshalKey decodes the configuration under key into rawVal. + UnmarshalKey(key string, rawVal any) error +} + +// ConfigKey is the TMS-relative configuration key the policy is read from, i.e. +// token.tms..identity.throttle in a Panurus configuration file. +const ConfigKey = "identity.throttle" + +// Config is the throttle policy as it appears in configuration. A zero value is valid and +// means "all defaults"; see Defaults for how individual zero fields are filled in. +type Config struct { + // Mode selects off / monitor / enforce. Empty selects DefaultMode. + Mode Mode `yaml:"mode,omitempty"` + // Rate is the metered signature operations per second allowed per principal. Zero + // selects DefaultRate; a negative value disables the policy, like ModeOff. + Rate float64 `yaml:"rate,omitempty"` + // Burst is the bucket capacity. Zero selects DefaultBurst; values below Rate are raised + // to Rate. + Burst float64 `yaml:"burst,omitempty"` + // Window is the evaluation period for the ratio thresholds. Zero selects DefaultWindow. + Window time.Duration `yaml:"window,omitempty"` + // MinSamples is the minimum number of observations in a window before a ratio can + // escalate a principal. Zero selects DefaultMinSamples. + MinSamples int `yaml:"minSamples,omitempty"` + // ErrorRateThreshold is the failing-operation fraction that escalates. Zero selects + // DefaultErrorRateThreshold; a value greater than 1 disables this trigger. + ErrorRateThreshold float64 `yaml:"errorRateThreshold,omitempty"` + // InvalidSignatureRateThreshold is the rejected-verification fraction that escalates. + // Zero selects DefaultInvalidSignatureRateThreshold; a value greater than 1 disables + // this trigger. + InvalidSignatureRateThreshold float64 `yaml:"invalidSignatureRateThreshold,omitempty"` + // QuotaReductionFactor multiplies Rate for a soft-limited principal. Zero selects + // DefaultQuotaReductionFactor. Must be in (0,1]. + QuotaReductionFactor float64 `yaml:"quotaReductionFactor,omitempty"` + // SoftDuration is the minimum time on a reduced quota. Zero selects DefaultSoftDuration. + SoftDuration time.Duration `yaml:"softDuration,omitempty"` + // BlockDuration is how long a blocked principal is refused. Zero selects + // DefaultBlockDuration. + BlockDuration time.Duration `yaml:"blockDuration,omitempty"` + // DeescalateAfter is the violation-free period required to restore the full quota. Zero + // selects DefaultDeescalateAfter. + DeescalateAfter time.Duration `yaml:"deescalateAfter,omitempty"` + // IdleTTL is how long per-principal state is kept after its last operation. Zero selects + // DefaultIdleTTL. + IdleTTL time.Duration `yaml:"idleTTL,omitempty"` +} + +// NewConfig reads the policy from the TMS configuration under ConfigKey and applies the +// defaults. A missing section yields the default policy. +func NewConfig(cs configService) (*Config, error) { + c := &Config{} + if err := cs.UnmarshalKey(ConfigKey, c); err != nil { + return nil, errors.Wrapf(err, "failed unmarshalling [%s]", ConfigKey) + } + + if err := c.Defaults(); err != nil { + return nil, err + } + + return c, nil +} + +// Defaults fills in every unset field and rejects values that cannot be honoured. Out-of-range +// values are an error rather than being clamped: a deployment that asks for a quota reduction +// factor of 3 has a mistake in its configuration, and silently treating it as 1 would leave +// the operator believing a policy is in force that is not. +func (c *Config) Defaults() error { + if c.Mode == "" { + c.Mode = DefaultMode + } + switch c.Mode { + case ModeOff, ModeMonitor, ModeEnforce: + default: + return errors.Errorf("invalid throttle mode [%s], expected one of [%s, %s, %s]", c.Mode, ModeOff, ModeMonitor, ModeEnforce) + } + + if c.Rate == 0 { + c.Rate = DefaultRate + } + if c.Burst == 0 { + c.Burst = DefaultBurst + } + if c.Window <= 0 { + c.Window = DefaultWindow + } + if c.MinSamples <= 0 { + c.MinSamples = DefaultMinSamples + } + if c.ErrorRateThreshold == 0 { + c.ErrorRateThreshold = DefaultErrorRateThreshold + } + if c.InvalidSignatureRateThreshold == 0 { + c.InvalidSignatureRateThreshold = DefaultInvalidSignatureRateThreshold + } + if c.QuotaReductionFactor == 0 { + c.QuotaReductionFactor = DefaultQuotaReductionFactor + } + if c.SoftDuration <= 0 { + c.SoftDuration = DefaultSoftDuration + } + if c.BlockDuration <= 0 { + c.BlockDuration = DefaultBlockDuration + } + if c.DeescalateAfter <= 0 { + c.DeescalateAfter = DefaultDeescalateAfter + } + if c.IdleTTL <= 0 { + c.IdleTTL = DefaultIdleTTL + } + + if c.ErrorRateThreshold < 0 { + return errors.Errorf("invalid errorRateThreshold [%g], expected a non-negative value (use > 1 to disable)", c.ErrorRateThreshold) + } + if c.InvalidSignatureRateThreshold < 0 { + return errors.Errorf("invalid invalidSignatureRateThreshold [%g], expected a non-negative value (use > 1 to disable)", c.InvalidSignatureRateThreshold) + } + if c.QuotaReductionFactor <= 0 || c.QuotaReductionFactor > 1 { + return errors.Errorf("invalid quotaReductionFactor [%g], expected a fraction in (0,1]", c.QuotaReductionFactor) + } + + return nil +} + +// Enabled reports whether the policy does anything at all. +func (c *Config) Enabled() bool { + return c.Mode != ModeOff && c.Rate > 0 +} + +// Enforcing reports whether the policy denies operations, as opposed to only reporting them. +func (c *Config) Enforcing() bool { + return c.Mode == ModeEnforce && c.Rate > 0 +} diff --git a/token/services/identity/throttle/config_test.go b/token/services/identity/throttle/config_test.go new file mode 100644 index 0000000000..cd0900fa19 --- /dev/null +++ b/token/services/identity/throttle/config_test.go @@ -0,0 +1,160 @@ +/* +Copyright IBM Corp. All Rights Reserved. + +SPDX-License-Identifier: Apache-2.0 +*/ + +package throttle_test + +import ( + "testing" + "time" + + "github.com/LFDT-Panurus/panurus/token/services/identity/throttle" + "github.com/hyperledger-labs/fabric-smart-client/pkg/utils/errors" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +// fakeConfigService serves one prepared configuration, or an error. +type fakeConfigService struct { + key string + config *throttle.Config + err error +} + +func (c *fakeConfigService) UnmarshalKey(key string, rawVal any) error { + c.key = key + if c.err != nil { + return c.err + } + if c.config == nil { + return nil + } + target, ok := rawVal.(*throttle.Config) + if !ok { + return errors.Errorf("unexpected target type [%T]", rawVal) + } + *target = *c.config + + return nil +} + +func TestNewConfigDefaults(t *testing.T) { + cs := &fakeConfigService{} + cfg, err := throttle.NewConfig(cs) + require.NoError(t, err) + + assert.Equal(t, "identity.throttle", cs.key, "the policy must be read from the documented key") + assert.Equal(t, throttle.DefaultMode, cfg.Mode) + assert.InDelta(t, float64(throttle.DefaultRate), cfg.Rate, 0) + assert.InDelta(t, float64(throttle.DefaultBurst), cfg.Burst, 0) + assert.Equal(t, throttle.DefaultWindow, cfg.Window) + assert.Equal(t, throttle.DefaultMinSamples, cfg.MinSamples) + assert.InDelta(t, throttle.DefaultErrorRateThreshold, cfg.ErrorRateThreshold, 0) + assert.InDelta(t, throttle.DefaultInvalidSignatureRateThreshold, cfg.InvalidSignatureRateThreshold, 0) + assert.InDelta(t, throttle.DefaultQuotaReductionFactor, cfg.QuotaReductionFactor, 0) + assert.Equal(t, throttle.DefaultSoftDuration, cfg.SoftDuration) + assert.Equal(t, throttle.DefaultBlockDuration, cfg.BlockDuration) + assert.Equal(t, throttle.DefaultDeescalateAfter, cfg.DeescalateAfter) + assert.Equal(t, throttle.DefaultIdleTTL, cfg.IdleTTL) + + assert.True(t, cfg.Enabled(), "the default policy observes") + assert.False(t, cfg.Enforcing(), "the default policy must not deny, since that changes a running deployment") +} + +func TestNewConfigKeepsConfiguredValues(t *testing.T) { + cs := &fakeConfigService{config: &throttle.Config{ + Mode: throttle.ModeEnforce, + Rate: 10, + Burst: 20, + Window: 30 * time.Second, + MinSamples: 5, + QuotaReductionFactor: 0.5, + }} + + cfg, err := throttle.NewConfig(cs) + require.NoError(t, err) + assert.Equal(t, throttle.ModeEnforce, cfg.Mode) + assert.InDelta(t, 10.0, cfg.Rate, 0) + assert.InDelta(t, 20.0, cfg.Burst, 0) + assert.Equal(t, 30*time.Second, cfg.Window) + assert.Equal(t, 5, cfg.MinSamples) + assert.InDelta(t, 0.5, cfg.QuotaReductionFactor, 0) + assert.True(t, cfg.Enforcing()) +} + +func TestNewConfigUnmarshalError(t *testing.T) { + _, err := throttle.NewConfig(&fakeConfigService{err: errors.New("bad yaml")}) + require.ErrorContains(t, err, "failed unmarshalling [identity.throttle]") +} + +func TestConfigDefaultsRejectsInvalidValues(t *testing.T) { + tests := []struct { + name string + config throttle.Config + errMsg string + }{ + { + name: "unknown mode", + config: throttle.Config{Mode: throttle.Mode("paranoid")}, + errMsg: "invalid throttle mode [paranoid]", + }, + { + name: "negative error rate threshold", + config: throttle.Config{ErrorRateThreshold: -0.5}, + errMsg: "invalid errorRateThreshold", + }, + { + name: "negative invalid signature rate threshold", + config: throttle.Config{InvalidSignatureRateThreshold: -0.1}, + errMsg: "invalid invalidSignatureRateThreshold", + }, + { + name: "quota reduction factor above one", + config: throttle.Config{QuotaReductionFactor: 3}, + errMsg: "invalid quotaReductionFactor", + }, + { + name: "negative quota reduction factor", + config: throttle.Config{QuotaReductionFactor: -1}, + errMsg: "invalid quotaReductionFactor", + }, + } + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + cfg := test.config + require.ErrorContains(t, cfg.Defaults(), test.errMsg) + }) + } +} + +func TestConfigEnabledAndEnforcing(t *testing.T) { + tests := []struct { + name string + config throttle.Config + enabled bool + enforcing bool + }{ + {name: "off", config: throttle.Config{Mode: throttle.ModeOff, Rate: 10}}, + {name: "monitor", config: throttle.Config{Mode: throttle.ModeMonitor, Rate: 10}, enabled: true}, + {name: "enforce", config: throttle.Config{Mode: throttle.ModeEnforce, Rate: 10}, enabled: true, enforcing: true}, + {name: "negative rate disables", config: throttle.Config{Mode: throttle.ModeEnforce, Rate: -1}}, + } + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + assert.Equal(t, test.enabled, test.config.Enabled()) + assert.Equal(t, test.enforcing, test.config.Enforcing()) + }) + } +} + +// TestConfigDefaultsIsIdempotent guards the wiring: sigpolicy defaults a configuration that +// NewConfig may already have defaulted, and a second pass must not move any value. +func TestConfigDefaultsIsIdempotent(t *testing.T) { + cfg := &throttle.Config{} + require.NoError(t, cfg.Defaults()) + first := *cfg + require.NoError(t, cfg.Defaults()) + assert.Equal(t, first, *cfg) +} diff --git a/token/services/identity/throttle/escalator_test.go b/token/services/identity/throttle/escalator_test.go new file mode 100644 index 0000000000..1269815e89 --- /dev/null +++ b/token/services/identity/throttle/escalator_test.go @@ -0,0 +1,641 @@ +/* +Copyright IBM Corp. All Rights Reserved. + +SPDX-License-Identifier: Apache-2.0 +*/ + +package throttle + +import ( + "context" + "strconv" + "sync" + "testing" + "time" + + "github.com/LFDT-Panurus/panurus/token" + "github.com/LFDT-Panurus/panurus/token/services/identity/sigobserve" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +const alice = "alice-hash" + +// testClock is a manually advanced clock, so that block expiry and de-escalation can be asserted +// without sleeping. +type testClock struct { + mu sync.Mutex + now time.Time +} + +func newTestClock() *testClock { + return &testClock{now: time.Date(2026, 7, 30, 12, 0, 0, 0, time.UTC)} +} + +func (c *testClock) Now() time.Time { + c.mu.Lock() + defer c.mu.Unlock() + + return c.now +} + +func (c *testClock) advance(d time.Duration) { + c.mu.Lock() + defer c.mu.Unlock() + c.now = c.now.Add(d) +} + +// recorder collects the escalation events an Escalator reports. +type recorder struct { + mu sync.Mutex + events []sigobserve.Event +} + +func (r *recorder) Observe(_ context.Context, e sigobserve.Event) { + r.mu.Lock() + defer r.mu.Unlock() + r.events = append(r.events, e) +} + +func (r *recorder) all() []sigobserve.Event { + r.mu.Lock() + defer r.mu.Unlock() + + return append([]sigobserve.Event(nil), r.events...) +} + +// levels returns the (level, reason) pairs reported, in order. +func (r *recorder) levels() [][2]string { + out := make([][2]string, 0, len(r.events)) + for _, e := range r.all() { + out = append(out, [2]string{e.Level, e.Reason}) + } + + return out +} + +func (r *recorder) last(t *testing.T) sigobserve.Event { + t.Helper() + events := r.all() + require.NotEmpty(t, events) + + return events[len(events)-1] +} + +// fakeGauge records the last count reported for each level. +type fakeGauge struct { + mu sync.Mutex + counts map[string]int +} + +func newFakeGauge() *fakeGauge { return &fakeGauge{counts: map[string]int{}} } + +func (g *fakeGauge) SetThrottledPrincipals(level string, n int) { + g.mu.Lock() + defer g.mu.Unlock() + g.counts[level] = n +} + +func (g *fakeGauge) get(level string) int { + g.mu.Lock() + defer g.mu.Unlock() + + return g.counts[level] +} + +// newTestEscalator returns an Escalator driven by clock, with cfg already defaulted. +func newTestEscalator(t *testing.T, cfg *Config, clock *testClock, opts ...Option) *Escalator { + t.Helper() + require.NoError(t, cfg.Defaults()) + + e := New(cfg, opts...) + t.Cleanup(e.Stop) + e.now = clock.Now + if e.buckets != nil { + e.buckets.SetNow(clock.Now) + } + + return e +} + +// enforcing returns a configuration that denies, with the ratio triggers wide open so that only +// what a test drives explicitly can escalate. +func enforcing() *Config { + return &Config{ + Mode: ModeEnforce, + Rate: 1000, + Burst: 1000, + MinSamples: 2, + ErrorRateThreshold: 0.5, + InvalidSignatureRateThreshold: 0.5, + SoftDuration: time.Minute, + BlockDuration: time.Minute, + DeescalateAfter: 2 * time.Minute, + } +} + +// observeInvalid reports n rejected verifications for principalID. +func observeInvalid(t *testing.T, e *Escalator, principalID string, n int) { + t.Helper() + for range n { + e.Observe(t.Context(), sigobserve.Event{ + Op: sigobserve.OpVerify, + Principal: principalID, + Outcome: sigobserve.OutcomeInvalid, + }) + } +} + +func TestEscalatorDisabled(t *testing.T) { + tests := []struct { + name string + config *Config + }{ + {name: "nil configuration"}, + {name: "mode off", config: &Config{Mode: ModeOff, Rate: 1}}, + {name: "non-positive rate", config: &Config{Mode: ModeEnforce, Rate: -1}}, + } + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + r := &recorder{} + e := New(test.config, WithObserver(r)) + t.Cleanup(e.Stop) + + for range 100 { + require.NoError(t, e.Allow(t.Context(), alice, sigobserve.OpGetSigner)) + } + observeInvalid(t, e, alice, 100) + + assert.Equal(t, LevelNormal, e.Level(alice)) + assert.Empty(t, r.all(), "a disabled policy reports nothing") + soft, blocked := e.Throttled() + assert.Zero(t, soft) + assert.Zero(t, blocked) + }) + } +} + +func TestEscalatorAllowsTrafficWithinQuota(t *testing.T) { + e := newTestEscalator(t, enforcing(), newTestClock()) + + for range 500 { + require.NoError(t, e.Allow(t.Context(), alice, sigobserve.OpGetSigner)) + } + assert.Equal(t, LevelNormal, e.Level(alice)) +} + +func TestEscalatorNeverThrottlesAnUnattributedOperation(t *testing.T) { + cfg := enforcing() + cfg.Rate, cfg.Burst = 1, 1 + e := newTestEscalator(t, cfg, newTestClock()) + + for range 50 { + require.NoError(t, e.Allow(t.Context(), "", sigobserve.OpGetSigner)) + } + observeInvalid(t, e, "", 50) + + e.mu.Lock() + defer e.mu.Unlock() + assert.Empty(t, e.principals, "an unattributed operation must not create per-principal state") +} + +func TestEscalatorQuotaExhaustionEscalates(t *testing.T) { + cfg := enforcing() + cfg.Rate, cfg.Burst = 1, 1 + r := &recorder{} + e := newTestEscalator(t, cfg, newTestClock(), WithObserver(r)) + + require.NoError(t, e.Allow(t.Context(), alice, sigobserve.OpGetSigner), "the first call spends the only token") + + err := e.Allow(t.Context(), alice, sigobserve.OpGetSigner) + require.Error(t, err) + require.ErrorIs(t, err, token.SignatureThrottled, "callers must be able to tell a denial from a failure") + assert.Contains(t, err.Error(), "get_signer") + assert.Equal(t, LevelSoft, e.Level(alice)) + + event := r.last(t) + assert.Equal(t, sigobserve.OpEscalation, event.Op) + assert.Equal(t, alice, event.Principal) + assert.Equal(t, string(LevelSoft), event.Level) + assert.Equal(t, ReasonRate, event.Reason) + assert.Equal(t, sigobserve.OutcomeOK, event.Outcome) + assert.Zero(t, event.Duration, "an escalation is state, not a timed call") +} + +func TestEscalatorMonitorModeEvaluatesButNeverDenies(t *testing.T) { + cfg := enforcing() + cfg.Mode = ModeMonitor + cfg.Rate, cfg.Burst = 1, 1 + r := &recorder{} + e := newTestEscalator(t, cfg, newTestClock(), WithObserver(r)) + + for range 10 { + require.NoError(t, e.Allow(t.Context(), alice, sigobserve.OpGetSigner), "monitor mode must not deny") + } + + assert.NotEqual(t, LevelNormal, e.Level(alice), "the decision is still evaluated") + assert.NotEmpty(t, r.all(), "and still reported, so thresholds can be tuned before enforcing") +} + +func TestEscalatorInvalidSignatureRateEscalates(t *testing.T) { + cfg := enforcing() + cfg.MinSamples = 4 + cfg.ErrorRateThreshold = 0.99 + cfg.InvalidSignatureRateThreshold = 0.5 + r := &recorder{} + e := newTestEscalator(t, cfg, newTestClock(), WithObserver(r)) + + // Two successes and two rejections: four samples, half of them invalid. + for range 2 { + e.Observe(t.Context(), sigobserve.Event{Op: sigobserve.OpVerify, Principal: alice, Outcome: sigobserve.OutcomeOK}) + } + observeInvalid(t, e, alice, 1) + assert.Equal(t, LevelNormal, e.Level(alice), "one rejection in three samples is not an attack") + + observeInvalid(t, e, alice, 1) + assert.Equal(t, LevelSoft, e.Level(alice)) + assert.Equal(t, ReasonInvalidSignatureRate, r.last(t).Reason) +} + +func TestEscalatorErrorRateEscalates(t *testing.T) { + cfg := enforcing() + cfg.MinSamples = 4 + cfg.ErrorRateThreshold = 0.5 + cfg.InvalidSignatureRateThreshold = 0.99 + r := &recorder{} + e := newTestEscalator(t, cfg, newTestClock(), WithObserver(r)) + + for range 4 { + e.Observe(t.Context(), sigobserve.Event{Op: sigobserve.OpGetSigner, Principal: alice, Outcome: sigobserve.OutcomeError}) + } + + assert.Equal(t, LevelSoft, e.Level(alice)) + assert.Equal(t, ReasonErrorRate, r.last(t).Reason) +} + +func TestEscalatorMinSamplesGatesTheRatios(t *testing.T) { + cfg := enforcing() + cfg.MinSamples = 50 + cfg.InvalidSignatureRateThreshold = 0.1 + e := newTestEscalator(t, cfg, newTestClock()) + + observeInvalid(t, e, alice, 49) + assert.Equal(t, LevelNormal, e.Level(alice), "a ratio over too few samples is noise") + + observeInvalid(t, e, alice, 1) + assert.Equal(t, LevelSoft, e.Level(alice)) +} + +func TestEscalatorIgnoresItsOwnEventsAndDenials(t *testing.T) { + cfg := enforcing() + cfg.MinSamples = 1 + cfg.InvalidSignatureRateThreshold = 0.1 + e := newTestEscalator(t, cfg, newTestClock()) + + // A self-referential observer chain must not recurse: escalation events are dropped. + for range 10 { + e.Observe(t.Context(), sigobserve.Event{ + Op: sigobserve.OpEscalation, + Principal: alice, + Outcome: sigobserve.OutcomeError, + Level: string(LevelSoft), + }) + } + // A denied operation never ran, so it is not a sample either. + for range 10 { + e.Observe(t.Context(), sigobserve.Event{ + Op: sigobserve.OpGetSigner, + Principal: alice, + Outcome: sigobserve.OutcomeThrottled, + }) + } + + assert.Equal(t, LevelNormal, e.Level(alice)) + e.mu.Lock() + defer e.mu.Unlock() + assert.Empty(t, e.principals) +} + +func TestEscalatorSecondViolationBlocks(t *testing.T) { + clock := newTestClock() + r := &recorder{} + e := newTestEscalator(t, enforcing(), clock, WithObserver(r)) + + observeInvalid(t, e, alice, 2) + require.Equal(t, LevelSoft, e.Level(alice)) + + // Violations that arrive while the principal is still serving its minimum SoftDuration + // must be absorbed: they re-arm the quiet-period clock but do not push to blocked. + observeInvalid(t, e, alice, 2) + require.Equal(t, LevelSoft, e.Level(alice), "a second violation within SoftDuration must not skip straight to blocked") + + // Only after the minimum soft period has elapsed can continued misbehaviour escalate. + clock.advance(61 * time.Second) + observeInvalid(t, e, alice, 2) + require.Equal(t, LevelBlocked, e.Level(alice)) + + err := e.Allow(t.Context(), alice, sigobserve.OpSign) + require.ErrorIs(t, err, token.SignatureThrottled) + assert.Contains(t, err.Error(), "blocked until") + assert.Equal(t, [][2]string{ + {string(LevelSoft), ReasonInvalidSignatureRate}, + {string(LevelBlocked), ReasonInvalidSignatureRate}, + }, r.levels()) +} + +// TestEscalatorSoftDurationIsHonouredBeforeBlocking pins the fix for the graduated-escalation +// bug: a principal must actually serve its reduced-quota period before continued misbehaviour +// can push it to blocked. Without the fix, request 11 reached soft and request 12 reached +// blocked, giving a principal no time at the reduced quota. +func TestEscalatorSoftDurationIsHonouredBeforeBlocking(t *testing.T) { + cfg := &Config{ + Mode: ModeEnforce, + Rate: 10, + Burst: 10, + MinSamples: 2, + ErrorRateThreshold: 0.99, + InvalidSignatureRateThreshold: 0.99, + SoftDuration: 5 * time.Minute, + BlockDuration: time.Minute, + DeescalateAfter: 2 * time.Minute, + } + clock := newTestClock() + r := &recorder{} + e := newTestEscalator(t, cfg, clock, WithObserver(r)) + + ctx := t.Context() + + // Requests 1-10 drain the burst bucket. + for range 10 { + require.NoError(t, e.Allow(ctx, alice, sigobserve.OpGetSigner)) + } + require.Equal(t, LevelNormal, e.Level(alice)) + + // Request 11: bucket is empty → normal → soft. + err := e.Allow(ctx, alice, sigobserve.OpGetSigner) + require.ErrorIs(t, err, token.SignatureThrottled) + require.Equal(t, LevelSoft, e.Level(alice), "request 11 must reach soft") + + // Request 12: bucket is still empty (soft quota has not refilled yet) but the principal + // is still within SoftDuration. It must stay at soft, not skip straight to blocked. + err = e.Allow(ctx, alice, sigobserve.OpGetSigner) + require.ErrorIs(t, err, token.SignatureThrottled) + require.Equal(t, LevelSoft, e.Level(alice), "request 12 must stay at soft — SoftDuration not yet elapsed") + + // Only one escalation event must have fired (normal → soft); there must be no blocked event. + assert.Equal(t, [][2]string{ + {string(LevelSoft), ReasonRate}, + }, r.levels(), "no blocked event while within SoftDuration") + + // After SoftDuration has elapsed a new threshold breach must escalate to blocked. + // Advance past SoftDuration (5 min) and deliver fresh violations via Observe so that + // maybeDeescalate (which runs only in decide/Allow) does not fire first. + clock.advance(6 * time.Minute) + observeInvalid(t, e, alice, 2) + require.Equal(t, LevelBlocked, e.Level(alice), "post-SoftDuration violation must reach blocked") +} + +func TestEscalatorBlockIsRearmedByAFreshViolation(t *testing.T) { + clock := newTestClock() + e := newTestEscalator(t, enforcing(), clock) + + observeInvalid(t, e, alice, 2) + require.Equal(t, LevelSoft, e.Level(alice)) + clock.advance(61 * time.Second) // past SoftDuration so the second wave can escalate + observeInvalid(t, e, alice, 2) + require.Equal(t, LevelBlocked, e.Level(alice)) + + // Halfway through the block, a fresh violation restarts it. + clock.advance(30 * time.Second) + observeInvalid(t, e, alice, 2) + + clock.advance(40 * time.Second) + require.ErrorIs(t, e.Allow(t.Context(), alice, sigobserve.OpSign), token.SignatureThrottled, + "the original block would have expired by now, the re-armed one has not") + + clock.advance(30 * time.Second) + require.NoError(t, e.Allow(t.Context(), alice, sigobserve.OpSign)) +} + +func TestEscalatorReleasesABlockedPrincipalToSoft(t *testing.T) { + clock := newTestClock() + r := &recorder{} + e := newTestEscalator(t, enforcing(), clock, WithObserver(r)) + + observeInvalid(t, e, alice, 2) + require.Equal(t, LevelSoft, e.Level(alice)) + clock.advance(61 * time.Second) // past SoftDuration so the second wave can escalate + observeInvalid(t, e, alice, 2) + require.Equal(t, LevelBlocked, e.Level(alice)) + + clock.advance(61 * time.Second) + require.NoError(t, e.Allow(t.Context(), alice, sigobserve.OpSign)) + assert.Equal(t, LevelSoft, e.Level(alice), "a released principal returns to a reduced quota, not to full") + assert.Equal(t, [2]string{string(LevelSoft), ReasonBlockExpired}, r.levels()[len(r.levels())-1]) +} + +func TestEscalatorDeescalatesAfterAQuietPeriod(t *testing.T) { + clock := newTestClock() + r := &recorder{} + e := newTestEscalator(t, enforcing(), clock, WithObserver(r)) + + observeInvalid(t, e, alice, 2) + require.Equal(t, LevelSoft, e.Level(alice)) + + // Within the minimum soft period, the level is held. + clock.advance(30 * time.Second) + require.NoError(t, e.Allow(t.Context(), alice, sigobserve.OpSign)) + assert.Equal(t, LevelSoft, e.Level(alice)) + + // Past both the minimum soft period and the violation-free period, the quota is restored. + clock.advance(2 * time.Minute) + require.NoError(t, e.Allow(t.Context(), alice, sigobserve.OpSign)) + assert.Equal(t, LevelNormal, e.Level(alice)) + assert.Equal(t, [2]string{string(LevelNormal), ReasonQuietPeriod}, r.levels()[len(r.levels())-1]) + + soft, blocked := e.Throttled() + assert.Zero(t, soft) + assert.Zero(t, blocked) +} + +// TestEscalatorSoftQuotaSlowsWithoutBlocking pins the invariant that a soft-limited principal can +// still make progress: a reduced bucket too small to ever hold one token would be an unannounced +// permanent block, and there would be no way back to normal. +func TestEscalatorSoftQuotaSlowsWithoutBlocking(t *testing.T) { + cfg := enforcing() + cfg.Rate, cfg.Burst = 4, 4 + cfg.QuotaReductionFactor = 0.1 // a reduced capacity of 0.4 tokens, rounded up to one + e := newTestEscalator(t, cfg, newTestClock()) + + observeInvalid(t, e, alice, 2) + require.Equal(t, LevelSoft, e.Level(alice)) + + require.NoError(t, e.Allow(t.Context(), alice, sigobserve.OpSign), "a soft-limited principal is slowed, not stopped") +} + +func TestEscalatorReportsThrottledCounts(t *testing.T) { + clock := newTestClock() + gauge := newFakeGauge() + e := newTestEscalator(t, enforcing(), clock, WithLevelGauge(gauge)) + + // alice reaches soft; bob reaches soft then, after SoftDuration, blocked. + observeInvalid(t, e, alice, 2) + observeInvalid(t, e, "bob-hash", 2) + clock.advance(61 * time.Second) // past SoftDuration so bob's second wave can escalate + observeInvalid(t, e, "bob-hash", 2) + + soft, blocked := e.Throttled() + assert.Equal(t, 1, soft) + assert.Equal(t, 1, blocked) + assert.Equal(t, 1, gauge.get(string(LevelSoft))) + assert.Equal(t, 1, gauge.get(string(LevelBlocked))) + + // Restoring alice's quota takes her out of the counts again. + clock.advance(3 * time.Minute) + require.NoError(t, e.Allow(t.Context(), alice, sigobserve.OpSign)) + soft, blocked = e.Throttled() + assert.Zero(t, soft) + assert.Equal(t, 1, blocked) + assert.Zero(t, gauge.get(string(LevelSoft))) +} + +func TestEscalatorWindowSlidesOut(t *testing.T) { + cfg := enforcing() + cfg.MinSamples = 3 + cfg.InvalidSignatureRateThreshold = 0.5 + cfg.Window = time.Minute + clock := newTestClock() + e := newTestEscalator(t, cfg, clock) + + observeInvalid(t, e, alice, 2) + require.Equal(t, LevelNormal, e.Level(alice)) + + // A full window later the earlier failures no longer count. + clock.advance(2 * time.Minute) + observeInvalid(t, e, alice, 2) + assert.Equal(t, LevelNormal, e.Level(alice), "failures that aged out must not escalate") + + observeInvalid(t, e, alice, 1) + assert.Equal(t, LevelSoft, e.Level(alice)) +} + +func TestEscalatorWindowSlidesBySlot(t *testing.T) { + cfg := enforcing() + cfg.MinSamples = 3 + cfg.InvalidSignatureRateThreshold = 0.5 + cfg.Window = time.Minute + clock := newTestClock() + e := newTestEscalator(t, cfg, clock) + + // One failure per ten-second slot: the window holds them all until the first ages out. + for range 2 { + observeInvalid(t, e, alice, 1) + clock.advance(10 * time.Second) + } + require.Equal(t, LevelNormal, e.Level(alice)) + + observeInvalid(t, e, alice, 1) + assert.Equal(t, LevelSoft, e.Level(alice), "three failures within the window escalate") +} + +func TestEscalatorEvictIdle(t *testing.T) { + cfg := enforcing() + cfg.IdleTTL = time.Minute + clock := newTestClock() + e := newTestEscalator(t, cfg, clock) + + require.NoError(t, e.Allow(t.Context(), "idle-hash", sigobserve.OpSign)) + observeInvalid(t, e, alice, 2) + require.Equal(t, LevelSoft, e.Level(alice)) + + clock.advance(2 * time.Minute) + e.evictIdle() + + e.mu.Lock() + _, idleKept := e.principals["idle-hash"] + _, throttledKept := e.principals[alice] + e.mu.Unlock() + + assert.False(t, idleKept, "an idle unthrottled principal costs memory for nothing") + assert.True(t, throttledKept, "a throttled principal's state is the only record that it is throttled") +} + +// TestEscalatorEvictIdleClearsBucketOverride pins the coupling between the escalator's +// evictIdle and BucketSet.ClearRate: when an idle principal is evicted, its bucket override +// must be cleared so the BucketSet's own idle eviction can reclaim the bucket. Without the +// ClearRate call the bucket stays pinned by its overridden flag and leaks indefinitely. +// +// The scenario is constructed by injecting a stale override directly — bypassing the normal +// transition path — to simulate the case where a bug or future code change leaves a +// LevelNormal principal with an overridden bucket. +func TestEscalatorEvictIdleClearsBucketOverride(t *testing.T) { + cfg := enforcing() + cfg.IdleTTL = time.Minute + clock := newTestClock() + e := newTestEscalator(t, cfg, clock) + + // Touch alice so her bucket and principal entry both exist. + require.NoError(t, e.Allow(t.Context(), alice, sigobserve.OpSign)) + require.Equal(t, LevelNormal, e.Level(alice)) + + // Inject a stale override on the bucket (simulating a bug where the override was not + // cleared when the principal returned to normal). + e.buckets.SetRate(alice, 0.1, 1) + require.Equal(t, 1, e.buckets.Len(), "pre-condition: bucket must exist") + + // Advance past IdleTTL and trigger the escalator's eviction sweep. + clock.advance(2 * time.Minute) + e.evictIdle() + + // The principal must be gone from the escalator … + e.mu.Lock() + _, kept := e.principals[alice] + e.mu.Unlock() + require.False(t, kept, "idle normal principal must be evicted") + + // … and the stale override must have been cleared, so the BucketSet's idle eviction can + // reclaim the bucket. Verify by triggering a BucketSet eviction sweep: since alice's + // bucket was last touched before the cutoff, it must be swept away. + e.buckets.EvictIdleNow() + assert.Equal(t, 0, e.buckets.Len(), "stale bucket must be reclaimed once its override is cleared") +} + +func TestEscalatorStopIsIdempotent(t *testing.T) { + cfg := enforcing() + cfg.Rate, cfg.Burst = 1, 1 + e := newTestEscalator(t, cfg, newTestClock()) + + e.Stop() + e.Stop() + + require.NoError(t, e.Allow(t.Context(), alice, sigobserve.OpSign)) + require.ErrorIs(t, e.Allow(t.Context(), alice, sigobserve.OpSign), token.SignatureThrottled, + "a stopped escalator keeps enforcing, it only stops reclaiming memory") +} + +func TestEscalatorConcurrentUse(t *testing.T) { + cfg := enforcing() + cfg.MinSamples = 1 + gauge := newFakeGauge() + e := newTestEscalator(t, cfg, newTestClock(), WithObserver(&recorder{}), WithLevelGauge(gauge)) + + ctx := t.Context() + var wg sync.WaitGroup + for i := range 8 { + wg.Add(1) + go func(i int) { + defer wg.Done() + principalID := strconv.Itoa(i) + "-hash" + for range 200 { + _ = e.Allow(ctx, principalID, sigobserve.OpGetSigner) + _ = e.Allow(ctx, alice, sigobserve.OpSign) + e.Observe(ctx, sigobserve.Event{Op: sigobserve.OpVerify, Principal: principalID, Outcome: sigobserve.OutcomeInvalid}) + e.Observe(ctx, sigobserve.Event{Op: sigobserve.OpSign, Principal: alice, Outcome: sigobserve.OutcomeOK}) + e.Level(principalID) + e.Throttled() + e.evictIdle() + } + }(i) + } + wg.Wait() +} diff --git a/token/services/identity/throttle/throttle.go b/token/services/identity/throttle/throttle.go new file mode 100644 index 0000000000..fd126cf8cd --- /dev/null +++ b/token/services/identity/throttle/throttle.go @@ -0,0 +1,524 @@ +/* +Copyright IBM Corp. All Rights Reserved. + +SPDX-License-Identifier: Apache-2.0 +*/ + +// Package throttle turns the observed behaviour of a principal into an automated defensive +// response on the signature surface. +// +// An Escalator is both an observer of Signer/Verifier operations and a gate in front of them. +// It watches, per principal, the request rate and the fraction of operations that fail or +// present a rejected signature; when either crosses its configured threshold the principal is +// moved up a level: +// +// normal -> full quota +// soft -> quota reduced by QuotaReductionFactor, for at least SoftDuration +// blocked -> operations refused for BlockDuration, then released back to soft +// +// A principal that goes DeescalateAfter without a violation is restored one level at a time. +// Every transition is reported as a sigobserve event, which is what makes alerting possible +// without scraping logs. +// +// Enforcement belongs at the client-facing boundary only. In particular it must not be +// applied inside driver validators: those resolve verifiers while validating a transaction, +// and denying them based on local per-node call history would make validation depend on which +// node performed it. Instrumentation is safe everywhere; the gate is not. +package throttle + +import ( + "context" + "math" + "sync" + "time" + + "github.com/LFDT-Panurus/panurus/token" + "github.com/LFDT-Panurus/panurus/token/services/identity/sigobserve" + "github.com/LFDT-Panurus/panurus/token/services/ratelimit" + "github.com/hyperledger-labs/fabric-smart-client/pkg/utils/errors" +) + +// Level is a principal's current throttle level. +type Level string + +const ( + // LevelNormal is the unthrottled level. + LevelNormal Level = "normal" + // LevelSoft is a reduced quota. + LevelSoft Level = "soft" + // LevelBlocked refuses every metered operation. + LevelBlocked Level = "blocked" +) + +// Escalation reasons, reported on OpEscalation events. +const ( + // ReasonRate is a principal exceeding its request quota. + ReasonRate = "rate" + // ReasonErrorRate is a principal whose operations fail too often. + ReasonErrorRate = "error_rate" + // ReasonInvalidSignatureRate is a principal presenting too many rejected signatures. + ReasonInvalidSignatureRate = "invalid_signature_rate" + // ReasonQuietPeriod is a de-escalation after a violation-free period. + ReasonQuietPeriod = "quiet_period" + // ReasonBlockExpired is the release of a blocked principal back to a reduced quota. + ReasonBlockExpired = "block_expired" +) + +// windowSlots is the number of sub-intervals a Window is divided into. Six gives a window +// that slides in ten-second steps at the default one-minute window: fine enough that a burst +// of failures does not linger for a full window after it stops, coarse enough that the state +// per principal stays a handful of integers. +const windowSlots = 6 + +// LevelGauge receives the number of principals currently held at each throttle level. It is +// the seam through which the policy reports its own state to metrics without depending on a +// metrics provider. +type LevelGauge interface { + // SetThrottledPrincipals reports that n principals are currently at level. + SetThrottledPrincipals(level string, n int) +} + +// Escalator applies an escalating throttle policy per principal. +// +// It is safe for concurrent use. Call Stop when it is no longer needed to release the token +// buckets' eviction goroutine. +type Escalator struct { + cfg *Config + buckets *ratelimit.BucketSet + observer sigobserve.Observer + gauge LevelGauge + + // now is the clock, indirected for tests. + now func() time.Time + + // mu guards principals and the per-level counts. + mu sync.Mutex + principals map[string]*principal + counts map[Level]int + + stopOnce sync.Once + stopped chan struct{} +} + +// principal is the policy state of one principal. +type principal struct { + level Level + // levelUntil is the earliest time the current level may be left. For LevelBlocked it is + // when the block expires; for LevelSoft it is the end of the minimum soft period. + levelUntil time.Time + // lastViolation is when the principal last crossed a threshold. + lastViolation time.Time + // lastSeen is when the principal last performed an operation, for idle eviction. + lastSeen time.Time + // slots is a ring of counters covering Window. + slots [windowSlots]slot + // slot is the index of the ring entry currently being filled. + slot int + // slotStart is when the current ring entry started. + slotStart time.Time +} + +// slot counts the operations observed during one sub-interval of a window. +type slot struct { + total int + errors int + invalid int +} + +// Option customizes an Escalator. +type Option func(*Escalator) + +// WithObserver installs the observer that escalation events are reported to. It must not be +// an observer chain that includes the Escalator itself; escalation events are ignored on the +// way in, so a mistake degrades to a dropped metric rather than a loop, but the chain to pass +// here is the reporting one (metrics plus audit log). +func WithObserver(o sigobserve.Observer) Option { + return func(e *Escalator) { e.observer = o } +} + +// WithLevelGauge installs the gauge that the number of throttled principals is reported to. +func WithLevelGauge(g LevelGauge) Option { + return func(e *Escalator) { e.gauge = g } +} + +// New returns an Escalator applying cfg. cfg must already have been defaulted (see +// Config.Defaults); NewConfig does that. A nil cfg, or one whose Mode is ModeOff, yields a +// disabled Escalator whose Allow always succeeds and whose Observe does nothing, so callers +// can wire it unconditionally. +func New(cfg *Config, opts ...Option) *Escalator { + if cfg == nil { + cfg = &Config{Mode: ModeOff} + } + + e := &Escalator{ + cfg: cfg, + observer: sigobserve.Nop, + now: time.Now, + principals: make(map[string]*principal), + counts: make(map[Level]int), + stopped: make(chan struct{}), + } + for _, opt := range opts { + opt(e) + } + + if !cfg.Enabled() { + return e + } + + e.buckets = ratelimit.NewBucketSet(cfg.Rate, cfg.Burst, cfg.IdleTTL, 0) + go e.evictLoop(cfg.IdleTTL) + + return e +} + +// Allow reports whether an operation on behalf of principal may proceed. It returns nil when +// the operation is allowed, and an error wrapping token.SignatureThrottled when the principal +// is currently blocked or has exhausted its quota. +// +// In ModeMonitor the decision is evaluated and reported but nil is always returned, so +// thresholds can be tuned against production traffic before they bite. +// +// An empty principal is never throttled: without attribution, a shared bucket would let +// unrelated callers throttle each other. +func (e *Escalator) Allow(ctx context.Context, principalID string, op sigobserve.Op) error { + if !e.cfg.Enabled() || principalID == "" { + return nil + } + + denied, reason := e.decide(ctx, principalID) + if !denied || !e.cfg.Enforcing() { + return nil + } + + return errors.Wrapf(token.SignatureThrottled, "operation [%s] by principal [%s] denied: %s", op, principalID, reason) +} + +// decide advances principalID's state and reports whether the operation should be denied, +// along with the reason. Whether the denial is acted upon is Allow's decision, so that +// monitor mode evaluates exactly what enforce mode would do. +func (e *Escalator) decide(ctx context.Context, principalID string) (denied bool, reason string) { + e.mu.Lock() + + p := e.principalFor(principalID) + p.lastSeen = e.now() + e.advanceWindow(p) + + // A block is checked before the bucket so that a blocked principal is not also charged + // for the attempt: it is already paying with the block. + if p.level == LevelBlocked { + if e.now().Before(p.levelUntil) { + until := p.levelUntil.UTC().Format(time.RFC3339) + e.mu.Unlock() + + return true, "principal is blocked until " + until + } + // The block has expired: release to a reduced quota rather than straight to full. + e.transition(ctx, principalID, p, LevelSoft, ReasonBlockExpired) + } + e.maybeDeescalate(ctx, principalID, p) + e.mu.Unlock() + + if e.buckets.Take(principalID) { + return false, "" + } + + e.mu.Lock() + e.escalate(ctx, principalID, p, ReasonRate) + level := p.level + e.mu.Unlock() + + return true, "principal exceeded its quota and is now at level " + string(level) +} + +// Observe records the outcome of an operation and escalates the principal when the observed +// failure ratios cross their thresholds. +// +// Every observed operation contributes to the window's sample count, so the ratios are fractions +// of what the principal actually did. Denied operations are the exception: they never ran, and +// counting them would let a throttled principal dilute the very ratio that throttled it. +func (e *Escalator) Observe(ctx context.Context, ev sigobserve.Event) { + // Escalation events are the Escalator's own output. Ignoring them here keeps an + // accidentally self-referential observer chain from recursing. + if !e.cfg.Enabled() || ev.Principal == "" || ev.Op == sigobserve.OpEscalation { + return + } + if ev.Outcome == sigobserve.OutcomeThrottled { + return + } + + e.mu.Lock() + defer e.mu.Unlock() + + p := e.principalFor(ev.Principal) + p.lastSeen = e.now() + e.advanceWindow(p) + p.slots[p.slot].total++ + switch ev.Outcome { + case sigobserve.OutcomeError: + p.slots[p.slot].errors++ + case sigobserve.OutcomeInvalid: + p.slots[p.slot].invalid++ + case sigobserve.OutcomeOK, sigobserve.OutcomeThrottled: + // A success moves the sample count only: there is no threshold it can cross. + return + default: + return + } + + total, errCount, invalid := e.totals(p) + if total < e.cfg.MinSamples { + return + } + + // Invalid signatures are checked first: they are the stronger signal, and reporting the + // stronger reason is more useful to whoever reads the escalation event. + if e.cfg.InvalidSignatureRateThreshold > 0 && float64(invalid)/float64(total) >= e.cfg.InvalidSignatureRateThreshold { + e.escalate(ctx, ev.Principal, p, ReasonInvalidSignatureRate) + + return + } + if e.cfg.ErrorRateThreshold > 0 && float64(errCount)/float64(total) >= e.cfg.ErrorRateThreshold { + e.escalate(ctx, ev.Principal, p, ReasonErrorRate) + } +} + +// Level reports principalID's current level, without advancing any timer. It is meant for +// tests and for operator tooling. +func (e *Escalator) Level(principalID string) Level { + e.mu.Lock() + defer e.mu.Unlock() + + p, ok := e.principals[principalID] + if !ok { + return LevelNormal + } + + return p.level +} + +// Throttled reports how many principals are currently held at each level above normal. +func (e *Escalator) Throttled() (soft int, blocked int) { + e.mu.Lock() + defer e.mu.Unlock() + + return e.counts[LevelSoft], e.counts[LevelBlocked] +} + +// Stop releases the resources held by the Escalator, including its background goroutines. It +// is idempotent, and Allow keeps working after it returns. +func (e *Escalator) Stop() { + e.stopOnce.Do(func() { + close(e.stopped) + if e.buckets != nil { + e.buckets.Stop() + } + }) +} + +// principalFor returns principalID's state, creating it at LevelNormal when new. Callers must +// hold e.mu. +func (e *Escalator) principalFor(principalID string) *principal { + p, ok := e.principals[principalID] + if ok { + return p + } + + now := e.now() + p = &principal{level: LevelNormal, lastSeen: now, slotStart: now} + e.principals[principalID] = p + + return p +} + +// advanceWindow rolls the ring forward to cover the current time, clearing the slots that +// have aged out. Callers must hold e.mu. +func (e *Escalator) advanceWindow(p *principal) { + slotDuration := e.cfg.Window / windowSlots + if slotDuration <= 0 { + return + } + + elapsed := e.now().Sub(p.slotStart) + if elapsed < slotDuration { + return + } + + steps := int(elapsed / slotDuration) + if steps >= windowSlots { + // The whole window has aged out. + p.slots = [windowSlots]slot{} + p.slot = 0 + p.slotStart = e.now() + + return + } + + for range steps { + p.slot = (p.slot + 1) % windowSlots + p.slots[p.slot] = slot{} + } + p.slotStart = p.slotStart.Add(time.Duration(steps) * slotDuration) +} + +// totals sums the ring. Callers must hold e.mu. +func (e *Escalator) totals(p *principal) (total int, errCount int, invalid int) { + for _, s := range p.slots { + total += s.total + errCount += s.errors + invalid += s.invalid + } + + return total, errCount, invalid +} + +// escalate moves p one level up and records the violation. A principal already blocked has +// its block re-armed rather than being pushed further, since there is no level above blocked. +// Callers must hold e.mu. +func (e *Escalator) escalate(ctx context.Context, principalID string, p *principal, reason string) { + now := e.now() + + // A soft-limited principal that is still serving its minimum SoftDuration has already + // been penalised for this episode. Absorb the violation (re-arming the clock so the + // quiet-period counter restarts) without pushing it to blocked. This preserves the + // graduated response: normal → soft (reduced quota) → blocked, where "soft" lasts at + // least SoftDuration before the next escalation can fire. + // + // A blocked principal is intentionally excluded from this guard: a fresh violation + // while blocked must re-arm the block deadline (there is no higher level, and extending + // the block is the correct response). + if p.level == LevelSoft && now.Before(p.levelUntil) { + p.lastViolation = now + return + } + + p.lastViolation = now + + switch p.level { + case LevelNormal: + e.transition(ctx, principalID, p, LevelSoft, reason) + case LevelSoft, LevelBlocked: + e.transition(ctx, principalID, p, LevelBlocked, reason) + } +} + +// maybeDeescalate restores one level when the principal has served its minimum time and gone +// DeescalateAfter without a violation. Callers must hold e.mu. +func (e *Escalator) maybeDeescalate(ctx context.Context, principalID string, p *principal) { + if p.level != LevelSoft { + return + } + + now := e.now() + if now.Before(p.levelUntil) || now.Sub(p.lastViolation) < e.cfg.DeescalateAfter { + return + } + + e.transition(ctx, principalID, p, LevelNormal, ReasonQuietPeriod) +} + +// transition moves p to level, applies the level's quota to the principal's bucket, updates +// the per-level counts and reports the change. Callers must hold e.mu. +// +// Reporting happens with the lock held. The observers on this path are a metrics update and a +// log line - both non-blocking - and a level change is rare compared to the operations that +// cause it, so the simpler locking is worth more here than the shorter critical section. +func (e *Escalator) transition(ctx context.Context, principalID string, p *principal, level Level, reason string) { + if p.level == level && level != LevelBlocked { + // Nothing to do, except for a block, which is re-armed on every fresh violation. + return + } + + // Only the levels above normal are counted: normal is the absence of throttling, and + // counting it would turn the gauge into a population count of every principal seen. + if p.level != LevelNormal { + e.counts[p.level]-- + if e.counts[p.level] <= 0 { + delete(e.counts, p.level) + } + } + if level != LevelNormal { + e.counts[level]++ + } + p.level = level + + now := e.now() + switch level { + case LevelNormal: + p.levelUntil = time.Time{} + e.buckets.ClearRate(principalID) + case LevelSoft: + p.levelUntil = now.Add(e.cfg.SoftDuration) + // SetRate clamps the balance to the new, smaller capacity, so a principal cannot + // carry a full default bucket's worth of credit into its reduced quota. The capacity + // keeps room for one token: a bucket that can never hold a whole token would refuse + // every request, which is what LevelBlocked is for, and a principal reduced below that + // could never earn its way back out of soft. + reducedBurst := math.Max(e.cfg.Burst*e.cfg.QuotaReductionFactor, 1) + e.buckets.SetRate(principalID, e.cfg.Rate*e.cfg.QuotaReductionFactor, reducedBurst) + case LevelBlocked: + p.levelUntil = now.Add(e.cfg.BlockDuration) + } + + // Counters carried over from the previous level would immediately re-trigger the + // threshold that caused the transition, so each level starts from a clean window. + p.slots = [windowSlots]slot{} + p.slot = 0 + p.slotStart = now + + e.report(ctx, principalID, level, reason) +} + +// report emits the escalation event and refreshes the level gauge. Callers must hold e.mu. +func (e *Escalator) report(ctx context.Context, principalID string, level Level, reason string) { + e.observer.Observe(ctx, sigobserve.Event{ + Op: sigobserve.OpEscalation, + Principal: principalID, + Role: sigobserve.RoleUnknown, + Outcome: sigobserve.OutcomeOK, + Level: string(level), + Reason: reason, + }) + + if e.gauge != nil { + e.gauge.SetThrottledPrincipals(string(LevelSoft), e.counts[LevelSoft]) + e.gauge.SetThrottledPrincipals(string(LevelBlocked), e.counts[LevelBlocked]) + } +} + +// evictLoop drops the state of principals that have been idle for longer than IdleTTL, so +// memory stays proportional to recently active principals. Principals above LevelNormal are +// kept: their state is the only record that they are being throttled. +func (e *Escalator) evictLoop(interval time.Duration) { + if interval <= 0 { + interval = DefaultIdleTTL + } + ticker := time.NewTicker(interval) + defer ticker.Stop() + + for { + select { + case <-e.stopped: + return + case <-ticker.C: + e.evictIdle() + } + } +} + +// evictIdle performs one eviction sweep. +func (e *Escalator) evictIdle() { + e.mu.Lock() + defer e.mu.Unlock() + + cutoff := e.now().Add(-e.cfg.IdleTTL) + for id, p := range e.principals { + if p.level == LevelNormal && p.lastSeen.Before(cutoff) { + // Clear the override before dropping the principal so the BucketSet's own + // idle eviction can reclaim the bucket. Without this, the bucket stays pinned + // by its overridden flag even after the principal that set it is gone. + e.buckets.ClearRate(id) + delete(e.principals, id) + } + } +} diff --git a/token/services/ratelimit/bucket.go b/token/services/ratelimit/bucket.go new file mode 100644 index 0000000000..81a5728804 --- /dev/null +++ b/token/services/ratelimit/bucket.go @@ -0,0 +1,269 @@ +/* +Copyright IBM Corp. All Rights Reserved. + +SPDX-License-Identifier: Apache-2.0 +*/ + +// Package ratelimit provides a reusable set of per-key token buckets. +// +// It carries no policy of its own: it neither decides what a key is nor what happens when a +// key runs out of tokens, so the same mechanism serves callers whose quota is fixed (a plain +// rate limit) and callers that adjust a single key's quota at runtime (an escalating +// throttle - see token/services/identity/throttle). +package ratelimit + +import ( + "math" + "sync" + "time" +) + +const ( + // DefaultIdleTTL is how long a key's bucket is kept after its last request before being + // evicted, so that memory stays proportional to the set of recently active keys rather + // than to all keys ever seen. + DefaultIdleTTL = 10 * time.Minute + // DefaultCleanupInterval is how often idle buckets are swept. + DefaultCleanupInterval = time.Minute +) + +// BucketSet is a set of per-key token buckets. Every key gets its own bucket, created full +// on first use and refilled at rate tokens per second up to burst tokens, so one key's +// traffic never consumes another's budget. Buckets are created lazily and evicted once +// idle, bounding memory to the recently active keys. +// +// A BucketSet is safe for concurrent use by multiple goroutines. +type BucketSet struct { + // rate is the default refill speed in tokens per second. When it is not positive the + // set is unmetered and Take always succeeds. + rate float64 + // burst is the default bucket capacity in tokens. + burst float64 + // idleTTL is how long a bucket without an override survives without requests. + idleTTL time.Duration + // now is the clock, indirected for tests. + now func() time.Time + + // mu guards buckets and the state of each bucket in it. A single mutex is enough: the + // critical section is a map lookup and a handful of float operations. + mu sync.Mutex + buckets map[string]*bucket + + stopOnce sync.Once + stopped chan struct{} +} + +// bucket is one key's token bucket. tokens is the balance as of last. When overridden is +// set, rate and burst replace the set's defaults for this key alone and the bucket is +// exempt from idle eviction, so that a reduced quota is never silently restored. +type bucket struct { + tokens float64 + last time.Time + rate float64 + burst float64 + overridden bool +} + +// NewBucketSet returns a set whose buckets refill at rate tokens per second with a capacity +// of burst tokens. +// +// Zero or negative values select sensible substitutes: a non-positive rate yields an +// unmetered set, a burst below rate is raised to rate (a bucket must hold at least one +// second's worth of refill to sustain that rate), and a non-positive idleTTL or +// cleanupInterval falls back to DefaultIdleTTL / DefaultCleanupInterval. +// +// Call Stop when the set is no longer needed to release its eviction goroutine. +func NewBucketSet(rate, burst float64, idleTTL, cleanupInterval time.Duration) *BucketSet { + s := &BucketSet{ + rate: rate, + burst: math.Max(burst, rate), + idleTTL: idleTTL, + now: time.Now, + buckets: make(map[string]*bucket), + stopped: make(chan struct{}), + } + + if s.rate <= 0 { + // Nothing to meter and nothing to evict: no goroutine is started, and Stop stays + // safe to call. + return s + } + + if cleanupInterval <= 0 { + cleanupInterval = DefaultCleanupInterval + } + if s.idleTTL <= 0 { + s.idleTTL = DefaultIdleTTL + } + // Evicting a bucket resets it to full, which is only free once it would have refilled + // completely anyway. Keep idle buckets at least that long so eviction can never hand a + // throttled key a fresh budget. + if refill := time.Duration(s.burst / s.rate * float64(time.Second)); s.idleTTL < refill { + s.idleTTL = refill + } + + go s.evictLoop(cleanupInterval) + + return s +} + +// Metered reports whether the set enforces any limit at all. An unmetered set (built with a +// non-positive rate) lets every Take succeed. +func (s *BucketSet) Metered() bool { + return s.rate > 0 +} + +// Take refills key's bucket for the elapsed time and consumes one token from it, reporting +// whether a token was available. An unmetered set always reports true. +func (s *BucketSet) Take(key string) bool { + if s.rate <= 0 { + return true + } + + s.mu.Lock() + defer s.mu.Unlock() + + b := s.bucketFor(key) + if b.tokens < 1 { + return false + } + b.tokens-- + + return true +} + +// SetRate replaces the quota of a single key with rate tokens per second and a capacity of +// burst, leaving every other key on the set's defaults. It is how a caller narrows the +// budget of one misbehaving principal without rebuilding the set. +// +// The current balance is clamped to the new capacity, so lowering a quota cannot hand the +// key more tokens than the new bucket holds; raising it never grants the difference +// retroactively either, the bucket simply refills faster from where it is. A key with an +// override is kept until ClearRate is called, so idle eviction cannot restore the default +// quota behind the caller's back. +// +// A non-positive rate is ignored: an unmetered exception for a single key would be a +// footgun, and the caller that wants one can stop consulting the set for that key. +func (s *BucketSet) SetRate(key string, rate, burst float64) { + if rate <= 0 { + return + } + + s.mu.Lock() + defer s.mu.Unlock() + + b := s.bucketFor(key) + b.rate = rate + b.burst = math.Max(burst, rate) + b.overridden = true + b.tokens = math.Min(b.tokens, b.burst) +} + +// ClearRate drops key's quota override, returning it to the set's defaults and making it +// eligible for idle eviction again. The balance is kept, and clamped to the default +// capacity: a key coming back from a reduced quota refills towards the default rather than +// jumping straight to a full default bucket. +func (s *BucketSet) ClearRate(key string) { + s.mu.Lock() + defer s.mu.Unlock() + + b, ok := s.buckets[key] + if !ok { + return + } + b.rate = s.rate + b.burst = s.burst + b.overridden = false + b.tokens = math.Min(b.tokens, s.burst) +} + +// Reset discards key's bucket, including any quota override, so its next Take starts from a +// full default bucket. It is meant for tests and for administrative "forgive this key" +// actions, not for the metering path. +func (s *BucketSet) Reset(key string) { + s.mu.Lock() + defer s.mu.Unlock() + + delete(s.buckets, key) +} + +// Len returns the number of buckets currently held. It is exported for tests and for +// gauges reporting how much state the set has accumulated. +func (s *BucketSet) Len() int { + s.mu.Lock() + defer s.mu.Unlock() + + return len(s.buckets) +} + +// EvictIdleNow runs one eviction sweep immediately, outside of the background ticker. It is +// intended for tests that need deterministic control over when idle buckets are reclaimed. +func (s *BucketSet) EvictIdleNow() { + s.evictIdle() +} + +// SetNow replaces the clock used by the set. It is intended for tests that need a manually +// advanced clock; callers must call it before any other method on the set. +func (s *BucketSet) SetNow(fn func() time.Time) { + s.now = fn +} + +// Stop terminates the eviction goroutine. Buckets are left in place, so a set that is still +// consulted after Stop keeps enforcing its limits; it simply stops reclaiming the memory of +// idle keys. Stop is idempotent. +func (s *BucketSet) Stop() { + s.stopOnce.Do(func() { close(s.stopped) }) +} + +// bucketFor returns key's bucket, creating it full when the key is new and refilling it for +// the time elapsed since its last update. Callers must hold s.mu. +func (s *BucketSet) bucketFor(key string) *bucket { + now := s.now() + b, ok := s.buckets[key] + if !ok { + // A key not seen recently starts with a full bucket at the set's defaults. + b = &bucket{tokens: s.burst, last: now, rate: s.rate, burst: s.burst} + s.buckets[key] = b + + return b + } + + if elapsed := now.Sub(b.last); elapsed > 0 { + b.tokens = math.Min(b.burst, b.tokens+elapsed.Seconds()*b.rate) + b.last = now + } + + return b +} + +// evictLoop sweeps idle buckets until Stop is called. +func (s *BucketSet) evictLoop(interval time.Duration) { + ticker := time.NewTicker(interval) + defer ticker.Stop() + + for { + select { + case <-s.stopped: + return + case <-ticker.C: + s.evictIdle() + } + } +} + +// evictIdle drops the buckets of keys that have made no request within idleTTL. Such a +// bucket has already refilled to capacity, so dropping it loses no accounting. Keys with a +// quota override are skipped as a safety net: the caller is expected to call ClearRate before +// evicting a principal, but if it does not, the bucket is retained rather than silently +// restoring the default quota for a key that is still being throttled. +func (s *BucketSet) evictIdle() { + s.mu.Lock() + defer s.mu.Unlock() + + cutoff := s.now().Add(-s.idleTTL) + for key, b := range s.buckets { + if !b.overridden && b.last.Before(cutoff) { + delete(s.buckets, key) + } + } +} diff --git a/token/services/ratelimit/bucket_test.go b/token/services/ratelimit/bucket_test.go new file mode 100644 index 0000000000..d5a6fb6325 --- /dev/null +++ b/token/services/ratelimit/bucket_test.go @@ -0,0 +1,283 @@ +/* +Copyright IBM Corp. All Rights Reserved. + +SPDX-License-Identifier: Apache-2.0 +*/ + +package ratelimit + +import ( + "strconv" + "sync" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +// testClock is a manually advanced clock, so that refill and eviction can be asserted without +// sleeping. +type testClock struct { + mu sync.Mutex + now time.Time +} + +func newTestClock() *testClock { + return &testClock{now: time.Date(2026, 7, 30, 12, 0, 0, 0, time.UTC)} +} + +func (c *testClock) Now() time.Time { + c.mu.Lock() + defer c.mu.Unlock() + + return c.now +} + +func (c *testClock) advance(d time.Duration) { + c.mu.Lock() + defer c.mu.Unlock() + c.now = c.now.Add(d) +} + +// newTestBucketSet returns a set driven by clock, with the eviction goroutine already stopped so +// that only the explicit evictIdle calls in a test have any effect. +func newTestBucketSet(t *testing.T, rate, burst float64, idleTTL time.Duration, clock *testClock) *BucketSet { + t.Helper() + + s := NewBucketSet(rate, burst, idleTTL, time.Hour) + t.Cleanup(s.Stop) + s.now = clock.Now + + return s +} + +func TestNewBucketSetDefaults(t *testing.T) { + t.Run("burst below rate is raised to rate", func(t *testing.T) { + s := NewBucketSet(10, 2, time.Minute, time.Hour) + t.Cleanup(s.Stop) + assert.InDelta(t, 10.0, s.burst, 0) + }) + + t.Run("idle ttl covers a full refill", func(t *testing.T) { + // 20 tokens at 2/s takes ten seconds to refill, which is longer than the requested TTL. + s := NewBucketSet(2, 20, time.Second, time.Hour) + t.Cleanup(s.Stop) + assert.Equal(t, 10*time.Second, s.idleTTL) + }) + + t.Run("non-positive idle ttl and cleanup interval fall back", func(t *testing.T) { + s := NewBucketSet(1000, 1000, 0, 0) + t.Cleanup(s.Stop) + assert.Equal(t, DefaultIdleTTL, s.idleTTL) + }) + + t.Run("non-positive rate is unmetered", func(t *testing.T) { + s := NewBucketSet(0, 10, time.Minute, time.Minute) + t.Cleanup(s.Stop) + assert.False(t, s.Metered()) + for range 100 { + assert.True(t, s.Take("a")) + } + assert.Equal(t, 0, s.Len(), "an unmetered set should not accumulate buckets") + }) +} + +func TestBucketSetTakeExhaustsAndRefills(t *testing.T) { + clock := newTestClock() + s := newTestBucketSet(t, 2, 4, time.Hour, clock) + + require.True(t, s.Metered()) + for i := range 4 { + assert.True(t, s.Take("alice"), "token %d should be available", i) + } + assert.False(t, s.Take("alice"), "the bucket should be empty") + + // Half a second at two tokens per second is one token. + clock.advance(500 * time.Millisecond) + assert.True(t, s.Take("alice")) + assert.False(t, s.Take("alice")) + + // Refill never exceeds the capacity. + clock.advance(time.Hour) + for range 4 { + assert.True(t, s.Take("alice")) + } + assert.False(t, s.Take("alice")) +} + +func TestBucketSetKeysAreIndependent(t *testing.T) { + clock := newTestClock() + s := newTestBucketSet(t, 1, 2, time.Hour, clock) + + require.True(t, s.Take("alice")) + require.True(t, s.Take("alice")) + require.False(t, s.Take("alice")) + + assert.True(t, s.Take("bob"), "bob must not pay for alice's traffic") + assert.Equal(t, 2, s.Len()) +} + +func TestBucketSetSetRate(t *testing.T) { + t.Run("clamps the balance to the new capacity", func(t *testing.T) { + clock := newTestClock() + s := newTestBucketSet(t, 10, 100, time.Hour, clock) + + // A full default bucket, then a quota cut to a quarter. + require.True(t, s.Take("alice")) + s.SetRate("alice", 2.5, 25) + + taken := 0 + for s.Take("alice") { + taken++ + require.Less(t, taken, 100, "the reduced bucket must not hold the default capacity") + } + assert.Equal(t, 25, taken, "the balance should be clamped to the reduced capacity") + }) + + t.Run("refills at the reduced rate", func(t *testing.T) { + clock := newTestClock() + s := newTestBucketSet(t, 10, 10, time.Hour, clock) + + s.SetRate("alice", 1, 1) + require.True(t, s.Take("alice")) + require.False(t, s.Take("alice")) + + clock.advance(500 * time.Millisecond) + assert.False(t, s.Take("alice"), "half a second is half a token at the reduced rate") + clock.advance(500 * time.Millisecond) + assert.True(t, s.Take("alice")) + }) + + t.Run("a non-positive rate is ignored", func(t *testing.T) { + clock := newTestClock() + s := newTestBucketSet(t, 1, 1, time.Hour, clock) + + s.SetRate("alice", 0, 0) + require.True(t, s.Take("alice")) + assert.False(t, s.Take("alice"), "the default quota should still apply") + }) + + t.Run("burst below rate is raised to rate", func(t *testing.T) { + clock := newTestClock() + s := newTestBucketSet(t, 10, 10, time.Hour, clock) + + s.SetRate("alice", 4, 1) + taken := 0 + for s.Take("alice") { + taken++ + require.Less(t, taken, 20, "the override capacity should be bounded") + } + assert.Equal(t, 4, taken) + }) +} + +func TestBucketSetClearRateKeepsTheBalance(t *testing.T) { + clock := newTestClock() + s := newTestBucketSet(t, 10, 10, time.Hour, clock) + + s.SetRate("alice", 1, 1) + require.True(t, s.Take("alice")) + require.False(t, s.Take("alice")) + + s.ClearRate("alice") + assert.False(t, s.Take("alice"), "clearing an override must not hand back a full default bucket") + + clock.advance(time.Second) + taken := 0 + for s.Take("alice") { + taken++ + require.Less(t, taken, 20, "the default capacity should bound the refill") + } + assert.Equal(t, 10, taken, "the key should be back on the default rate") +} + +func TestBucketSetClearRateOnUnknownKey(t *testing.T) { + clock := newTestClock() + s := newTestBucketSet(t, 1, 1, time.Hour, clock) + + s.ClearRate("nobody") + assert.Equal(t, 0, s.Len(), "clearing an unknown key must not create a bucket") +} + +func TestBucketSetReset(t *testing.T) { + clock := newTestClock() + s := newTestBucketSet(t, 10, 10, time.Hour, clock) + + s.SetRate("alice", 1, 1) + require.True(t, s.Take("alice")) + require.False(t, s.Take("alice")) + + s.Reset("alice") + assert.Equal(t, 0, s.Len()) + taken := 0 + for s.Take("alice") { + taken++ + require.Less(t, taken, 20, "a reset key should be back on the default capacity") + } + assert.Equal(t, 10, taken) +} + +func TestBucketSetEvictIdle(t *testing.T) { + clock := newTestClock() + s := newTestBucketSet(t, 10, 10, 30*time.Second, clock) + + require.True(t, s.Take("idle")) + require.True(t, s.Take("throttled")) + s.SetRate("throttled", 1, 1) + require.Equal(t, 2, s.Len()) + + clock.advance(31 * time.Second) + s.evictIdle() + + assert.Equal(t, 1, s.Len(), "only the key without an override should be evicted") + // The override survived, so the reduced quota is still in force. + require.True(t, s.Take("throttled")) + assert.False(t, s.Take("throttled")) +} + +func TestBucketSetEvictIdleKeepsActiveKeys(t *testing.T) { + clock := newTestClock() + s := newTestBucketSet(t, 10, 10, time.Minute, clock) + + require.True(t, s.Take("active")) + clock.advance(30 * time.Second) + require.True(t, s.Take("active")) + clock.advance(31 * time.Second) + s.evictIdle() + + assert.Equal(t, 1, s.Len(), "a key seen within the TTL should survive") +} + +func TestBucketSetStopIsIdempotent(t *testing.T) { + s := NewBucketSet(10, 10, time.Minute, time.Millisecond) + s.Stop() + s.Stop() + + // A stopped set keeps enforcing its limits. + for range 10 { + assert.True(t, s.Take("alice")) + } + assert.False(t, s.Take("alice")) +} + +func TestBucketSetConcurrentUse(t *testing.T) { + s := NewBucketSet(1000, 1000, time.Minute, time.Millisecond) + t.Cleanup(s.Stop) + + var wg sync.WaitGroup + for i := range 8 { + wg.Add(1) + go func(i int) { + defer wg.Done() + for range 200 { + s.Take("shared") + s.Take(strconv.Itoa(i)) + s.SetRate("shared", 100, 100) + s.ClearRate("shared") + s.Len() + } + }(i) + } + wg.Wait() +} diff --git a/token/services/ttx/auditor.go b/token/services/ttx/auditor.go index c209373222..83182cc36c 100644 --- a/token/services/ttx/auditor.go +++ b/token/services/ttx/auditor.go @@ -301,6 +301,13 @@ func (a *AuditingViewInitiator) verifyAuditorSignature(context view.Context, sig for _, auditorID := range a.tx.TokenService().PublicParametersManager().PublicParameters().Auditors() { v, err := a.tx.TokenService().SigService().AuditorVerifier(context.Context(), auditorID) if err != nil { + if errors.Is(err, token.SignatureThrottled) { + // The signature service is rate-limiting this node's own auditor lookup. + // Propagate as-is so the caller can distinguish a throttle from a verification + // failure and back off rather than logging a misleading "failed verifying auditor + // signature" error. + return nil, errors.Wrapf(err, "auditor verifier for [%s] rate-limited", auditorID) + } logger.DebugfContext(context.Context(), "failed to get auditor verifier for [%s]", auditorID) continue diff --git a/token/sig.go b/token/sig.go index 958e441e1b..3c649163f6 100644 --- a/token/sig.go +++ b/token/sig.go @@ -10,9 +10,17 @@ import ( "context" "github.com/LFDT-Panurus/panurus/token/driver" + "github.com/LFDT-Panurus/panurus/token/services/identity/sigobserve" "github.com/hyperledger-labs/fabric-smart-client/pkg/utils/errors" ) +// SignatureThrottled is the contract error returned (directly or wrapped) when a signature +// operation is denied because the requesting principal has exceeded its quota or is currently +// blocked by the throttle policy. Callers detect it with errors.Is to tell "you are asking too +// often" apart from "this identity is unknown" or "this signature is invalid", which is the +// difference between backing off and giving up. +var SignatureThrottled = errors.New("signature operation rate limit exceeded") + // Identity represents a generic identity type Identity = driver.Identity @@ -22,54 +30,130 @@ type Verifier = driver.Verifier // Signer models a signature signer type Signer = driver.Signer +// SignatureGate decides whether a signature operation on behalf of a principal may proceed. It +// is the seam through which a throttle policy is installed in front of the signature surface; +// package token deliberately depends on the interface only, so no policy implementation is +// pulled into the client-facing API. +// +// Implementations must be safe for concurrent use and must not block. Denials must return an +// error that satisfies errors.Is(err, SignatureThrottled). +type SignatureGate = sigobserve.Gate + // SignatureService gives access to signature verifiers and signers bound to identities known by // this service type SignatureService struct { deserializer driver.Deserializer identityProvider driver.IdentityProvider + + // observer receives the events this service produces. It only reports denials: the + // operations themselves are instrumented where they happen, in the identity provider and + // in the deserializer, so that calls arriving through other entry points are observed too + // and no operation is counted twice. + observer sigobserve.Observer + // gate, when set, may deny an operation before it runs. + gate SignatureGate +} + +// SignatureServiceOption customizes a SignatureService. +type SignatureServiceOption func(*SignatureService) + +// WithSignatureObserver installs the observer that denied operations are reported to. +func WithSignatureObserver(o sigobserve.Observer) SignatureServiceOption { + return func(s *SignatureService) { + if o != nil { + s.observer = o + } + } +} + +// WithSignatureGate installs the gate consulted before each signature operation. +func WithSignatureGate(g SignatureGate) SignatureServiceOption { + return func(s *SignatureService) { s.gate = g } } // NewSignatureService returns a instance of SignatureService -func NewSignatureService(deserializer driver.Deserializer, identityProvider driver.IdentityProvider) *SignatureService { - return &SignatureService{deserializer: deserializer, identityProvider: identityProvider} +func NewSignatureService(deserializer driver.Deserializer, identityProvider driver.IdentityProvider, opts ...SignatureServiceOption) *SignatureService { + s := &SignatureService{ + deserializer: deserializer, + identityProvider: identityProvider, + observer: sigobserve.Nop, + } + for _, opt := range opts { + opt(s) + } + + return s } -// AuditorVerifier returns a signature verifier for the given auditor identity +// AuditorVerifier returns a signature verifier for the given auditor identity. +// +// This operation is not gated: the identity always comes from the public parameters of the +// token system, so the set of principals is tiny, fixed and not attacker-controlled. Applying +// the rate-limit quota here would make DefaultRate a hard ceiling on transaction throughput +// for the node, not a per-counterparty abuse limit. The operation is still instrumented +// downstream in the deserializer. func (s *SignatureService) AuditorVerifier(ctx context.Context, id Identity) (Verifier, error) { return s.deserializer.GetAuditorVerifier(ctx, id) } // OwnerVerifier returns a signature verifier for the given owner identity func (s *SignatureService) OwnerVerifier(ctx context.Context, id Identity) (Verifier, error) { + if err := s.allow(ctx, sigobserve.OpOwnerVerifier, sigobserve.RoleOwner, id); err != nil { + return nil, err + } + return s.deserializer.GetOwnerVerifier(ctx, id) } // IssuerVerifier returns a signature verifier for the given issuer identity func (s *SignatureService) IssuerVerifier(ctx context.Context, id Identity) (Verifier, error) { + if err := s.allow(ctx, sigobserve.OpIssuerVerifier, sigobserve.RoleIssuer, id); err != nil { + return nil, err + } + return s.deserializer.GetIssuerVerifier(ctx, id) } -// GetSigner returns a signer bound to the given identity +// GetSigner returns a signer bound to the given identity. +// +// This operation is not gated: on the hot endorsement path it is called with the node's own +// long-term signing identity, so all of a node's traffic would be charged to a single bucket +// and DefaultRate would become a global TPS cap on endorsements. The operation is still +// instrumented downstream in the identity provider. func (s *SignatureService) GetSigner(ctx context.Context, id Identity) (Signer, error) { return s.identityProvider.GetSigner(ctx, id) } // RegisterSigner registers the pair (signer, verifier) bound to the given identity func (s *SignatureService) RegisterSigner(ctx context.Context, identity Identity, signer Signer, verifier Verifier) error { + if err := s.allow(ctx, sigobserve.OpRegisterSigner, sigobserve.RoleUnknown, identity); err != nil { + return err + } + return s.identityProvider.RegisterSigner(ctx, identity, signer, verifier, nil, false) } // RegisterEphemeralSigner registers the pair (signer, verifier) bound to the given identity only in memory func (s *SignatureService) RegisterEphemeralSigner(ctx context.Context, identity Identity, signer Signer, verifier Verifier) error { + if err := s.allow(ctx, sigobserve.OpRegisterSigner, sigobserve.RoleUnknown, identity); err != nil { + return err + } + return s.identityProvider.RegisterSigner(ctx, identity, signer, verifier, nil, true) } // AreMe returns the hashes of the passed identities that have a signer registered before +// +// The operation is not gated: it answers a question about local state and cannot report a +// denial, and returning "not mine" for an identity that is in fact ours would be a wrong +// answer rather than a refusal. func (s *SignatureService) AreMe(ctx context.Context, identities ...Identity) []string { return s.identityProvider.AreMe(ctx, identities...) } // IsMe returns true if for the given identity there is a signer registered +// +// As with AreMe, the operation is not gated: false would be a wrong answer, not a refusal. func (s *SignatureService) IsMe(ctx context.Context, party Identity) bool { return s.identityProvider.IsMe(ctx, party) } @@ -78,6 +162,9 @@ func (s *SignatureService) IsMe(ctx context.Context, party Identity) bool { func (s *SignatureService) GetAuditInfo(ctx context.Context, ids ...Identity) ([][]byte, error) { result := make([][]byte, 0, len(ids)) for _, id := range ids { + if err := s.allow(ctx, sigobserve.OpGetAuditInfo, sigobserve.RoleUnknown, id); err != nil { + return nil, err + } auditInfo, err := s.identityProvider.GetAuditInfo(ctx, id) if err != nil { return nil, errors.Wrapf(err, "failed to get audit info for identity [%s]", id) @@ -87,3 +174,20 @@ func (s *SignatureService) GetAuditInfo(ctx context.Context, ids ...Identity) ([ return result, nil } + +// allow consults the gate and reports a denial as a throttled event. It returns nil when no +// gate is installed, so an unconfigured service behaves exactly as before. +func (s *SignatureService) allow(ctx context.Context, op sigobserve.Op, role sigobserve.Role, id Identity) error { + if s.gate == nil { + return nil + } + + principal := id.UniqueID() + if err := s.gate.Allow(ctx, principal, op); err != nil { + sigobserve.Start(s.observer, op, principal, role).DoneThrottled(ctx, err) + + return err + } + + return nil +} diff --git a/token/sig_gate_test.go b/token/sig_gate_test.go new file mode 100644 index 0000000000..429c5aa8f6 --- /dev/null +++ b/token/sig_gate_test.go @@ -0,0 +1,285 @@ +/* +Copyright IBM Corp. All Rights Reserved. + +SPDX-License-Identifier: Apache-2.0 +*/ + +package token + +import ( + "context" + "sync" + "testing" + + "github.com/LFDT-Panurus/panurus/token/driver/mock" + "github.com/LFDT-Panurus/panurus/token/services/identity/sigobserve" + "github.com/hyperledger-labs/fabric-smart-client/pkg/utils/errors" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +// denyingGate refuses every operation, recording what it was asked about. +type denyingGate struct { + mu sync.Mutex + calls []sigobserve.Op + last string +} + +func (g *denyingGate) Allow(_ context.Context, principal string, op sigobserve.Op) error { + g.mu.Lock() + defer g.mu.Unlock() + g.calls = append(g.calls, op) + g.last = principal + + return errors.Wrapf(SignatureThrottled, "operation [%s] denied", op) +} + +func (g *denyingGate) ops() []sigobserve.Op { + g.mu.Lock() + defer g.mu.Unlock() + + return append([]sigobserve.Op(nil), g.calls...) +} + +// allowingGate permits every operation, recording the operations it was consulted about. +type allowingGate struct { + mu sync.Mutex + calls []sigobserve.Op +} + +func (g *allowingGate) Allow(_ context.Context, _ string, op sigobserve.Op) error { + g.mu.Lock() + defer g.mu.Unlock() + g.calls = append(g.calls, op) + + return nil +} + +func (g *allowingGate) count() int { + g.mu.Lock() + defer g.mu.Unlock() + + return len(g.calls) +} + +// gateRecorder collects the events the signature service reports. +type gateRecorder struct { + mu sync.Mutex + events []sigobserve.Event +} + +func (r *gateRecorder) Observe(_ context.Context, e sigobserve.Event) { + r.mu.Lock() + defer r.mu.Unlock() + r.events = append(r.events, e) +} + +func (r *gateRecorder) all() []sigobserve.Event { + r.mu.Lock() + defer r.mu.Unlock() + + return append([]sigobserve.Event(nil), r.events...) +} + +// gatedService is a SignatureService fronted by gate, with its collaborators exposed. +type gatedService struct { + service *SignatureService + deserializer *mock.Deserializer + provider *mock.IdentityProvider + events *gateRecorder +} + +func newGatedService(gate SignatureGate) *gatedService { + g := &gatedService{ + deserializer: &mock.Deserializer{}, + provider: &mock.IdentityProvider{}, + events: &gateRecorder{}, + } + g.service = NewSignatureService(g.deserializer, g.provider, + WithSignatureObserver(g.events), WithSignatureGate(gate)) + + return g +} + +// TestSignatureServiceDeniesEveryGatedOperation walks the whole client-facing surface, because a +// gate that covers only some of it leaves the rest of the surface as the way around the policy. +// +// AuditorVerifier and GetSigner are intentionally absent: they are not gated because the +// identities they use come from trusted fixed sources (public parameters and the node's own +// long-term identity, respectively). Gating them would make DefaultRate a hard TPS ceiling on +// normal transaction processing rather than a per-counterparty abuse limit. See +// TestSignatureServiceTrustedOperationsAreNotGated. +func TestSignatureServiceDeniesEveryGatedOperation(t *testing.T) { + id := Identity("an_identity") + tests := []struct { + name string + call func(s *SignatureService) error + op sigobserve.Op + role sigobserve.Role + }{ + { + name: "OwnerVerifier", + call: func(s *SignatureService) error { + _, err := s.OwnerVerifier(t.Context(), id) + + return err + }, + op: sigobserve.OpOwnerVerifier, + role: sigobserve.RoleOwner, + }, + { + name: "IssuerVerifier", + call: func(s *SignatureService) error { + _, err := s.IssuerVerifier(t.Context(), id) + + return err + }, + op: sigobserve.OpIssuerVerifier, + role: sigobserve.RoleIssuer, + }, + { + name: "RegisterSigner", + call: func(s *SignatureService) error { + return s.RegisterSigner(t.Context(), id, &mock.Signer{}, &mock.Verifier{}) + }, + op: sigobserve.OpRegisterSigner, + role: sigobserve.RoleUnknown, + }, + { + name: "RegisterEphemeralSigner", + call: func(s *SignatureService) error { + return s.RegisterEphemeralSigner(t.Context(), id, &mock.Signer{}, &mock.Verifier{}) + }, + op: sigobserve.OpRegisterSigner, + role: sigobserve.RoleUnknown, + }, + { + name: "GetAuditInfo", + call: func(s *SignatureService) error { + _, err := s.GetAuditInfo(t.Context(), id) + + return err + }, + op: sigobserve.OpGetAuditInfo, + role: sigobserve.RoleUnknown, + }, + } + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + gate := &denyingGate{} + g := newGatedService(gate) + + err := test.call(g.service) + require.Error(t, err) + require.ErrorIs(t, err, SignatureThrottled, "a denial must be distinguishable from a failure") + + assert.Equal(t, []sigobserve.Op{test.op}, gate.ops()) + assert.Equal(t, id.UniqueID(), gate.last, "the gate meters identity hashes, never raw identities") + + // The denial happens before the work, so nothing downstream is touched. + assert.Empty(t, g.deserializer.Invocations(), "a denied operation must not reach the deserializer") + assert.Empty(t, g.provider.Invocations(), "a denied operation must not reach the identity provider") + + events := g.events.all() + require.Len(t, events, 1) + assert.Equal(t, test.op, events[0].Op) + assert.Equal(t, test.role, events[0].Role) + assert.Equal(t, id.UniqueID(), events[0].Principal) + assert.Equal(t, sigobserve.OutcomeThrottled, events[0].Outcome) + assert.ErrorIs(t, events[0].Err, SignatureThrottled) + }) + } +} + +// TestSignatureServiceTrustedOperationsAreNotGated pins that AuditorVerifier and GetSigner +// bypass the gate entirely. Their principals come from trusted fixed sources — public +// parameters and the node's own identity — so there is no attacker-controlled input to +// defend against, and applying the rate quota would make DefaultRate a hard TPS ceiling on +// the node's own transaction throughput. +func TestSignatureServiceTrustedOperationsAreNotGated(t *testing.T) { + gate := &denyingGate{} + g := newGatedService(gate) + id := Identity("an_identity") + + // Both calls reach the downstream component even though the gate would deny them. + g.deserializer.GetAuditorVerifierReturns(&mock.Verifier{}, nil) + g.provider.GetSignerReturns(&mock.Signer{}, nil) + + _, err := g.service.AuditorVerifier(t.Context(), id) + require.NoError(t, err, "AuditorVerifier must not be gated") + + _, err = g.service.GetSigner(t.Context(), id) + require.NoError(t, err, "GetSigner must not be gated") + + assert.Empty(t, gate.ops(), "the gate must not be consulted for trusted fixed-identity operations") + assert.Empty(t, g.events.all(), "no denial events are emitted for ungated operations") + assert.Equal(t, 1, g.deserializer.GetAuditorVerifierCallCount(), "AuditorVerifier reaches the deserializer") + assert.Equal(t, 1, g.provider.GetSignerCallCount(), "GetSigner reaches the identity provider") +} + +// TestSignatureServiceReportsOnlyDenials pins the no-double-counting rule: the operations +// themselves are instrumented where they run, so this service reports denials and nothing else. +func TestSignatureServiceReportsOnlyDenials(t *testing.T) { + gate := &allowingGate{} + g := newGatedService(gate) + g.deserializer.GetOwnerVerifierReturns(&mock.Verifier{}, nil) + + _, err := g.service.OwnerVerifier(t.Context(), Identity("an_identity")) + require.NoError(t, err) + + assert.Equal(t, 1, gate.count(), "the gate is still consulted") + assert.Empty(t, g.events.all(), "an allowed operation is counted by the component that performs it") +} + +// TestSignatureServiceLocalQuestionsAreNotGated covers AreMe and IsMe: they answer a question +// about local state and have no way to say "refused", so gating them would turn a denial into the +// wrong answer. +func TestSignatureServiceLocalQuestionsAreNotGated(t *testing.T) { + gate := &denyingGate{} + g := newGatedService(gate) + id := Identity("an_identity") + g.provider.AreMeReturns([]string{id.UniqueID()}) + g.provider.IsMeReturns(true) + + assert.Equal(t, []string{id.UniqueID()}, g.service.AreMe(t.Context(), id)) + assert.True(t, g.service.IsMe(t.Context(), id)) + + assert.Empty(t, gate.ops(), "the gate must not be consulted for a question about local state") + assert.Empty(t, g.events.all()) +} + +// TestSignatureServiceWithoutAGateIsUnchanged pins the default: a service built without a policy +// behaves exactly as it did before the gate existed. +func TestSignatureServiceWithoutAGateIsUnchanged(t *testing.T) { + g := newGatedService(nil) + expected := &mock.Verifier{} + g.deserializer.GetOwnerVerifierReturns(expected, nil) + + verifier, err := g.service.OwnerVerifier(t.Context(), Identity("an_identity")) + require.NoError(t, err) + assert.Same(t, expected, verifier) + assert.Empty(t, g.events.all()) +} + +// TestSignatureServiceGetAuditInfoStopsAtTheFirstDenial guards a batch call: continuing past a +// denial would perform exactly the work the policy refused. +func TestSignatureServiceGetAuditInfoStopsAtTheFirstDenial(t *testing.T) { + gate := &denyingGate{} + g := newGatedService(gate) + + _, err := g.service.GetAuditInfo(t.Context(), Identity("first"), Identity("second")) + require.ErrorIs(t, err, SignatureThrottled) + assert.Len(t, gate.ops(), 1, "the second identity is never reached") + assert.Zero(t, g.provider.GetAuditInfoCallCount()) +} + +// TestSignatureServiceOptionsTolerateNil covers the wiring path where a driver has no +// observability stack to install. +func TestSignatureServiceOptionsTolerateNil(t *testing.T) { + s := NewSignatureService(&mock.Deserializer{}, &mock.IdentityProvider{}, + WithSignatureObserver(nil), WithSignatureGate(nil)) + + assert.NotNil(t, s.observer, "a nil observer must not replace the no-op one") + assert.Nil(t, s.gate) + require.NoError(t, s.allow(t.Context(), sigobserve.OpSign, sigobserve.RoleUnknown, Identity("an_identity"))) +} diff --git a/token/tms.go b/token/tms.go index 52e82db0eb..7227faec92 100644 --- a/token/tms.go +++ b/token/tms.go @@ -15,6 +15,7 @@ import ( "fmt" "github.com/LFDT-Panurus/panurus/token/driver" + "github.com/LFDT-Panurus/panurus/token/services/identity/sigobserve" "github.com/LFDT-Panurus/panurus/token/services/logging" "github.com/hyperledger-labs/fabric-smart-client/pkg/utils/errors" ) @@ -72,10 +73,11 @@ func NewManagementService( vaultProvider: vaultProvider, certificationClientProvider: certificationClientProvider, selectorManagerProvider: selectorManagerProvider, - signatureService: &SignatureService{ - deserializer: tms.Deserializer(), - identityProvider: tms.IdentityProvider(), - }, + signatureService: NewSignatureService( + tms.Deserializer(), + tms.IdentityProvider(), + signatureServiceOptions(tms)..., + ), } if err := ms.init(); err != nil { return nil, err @@ -84,6 +86,37 @@ func NewManagementService( return ms, nil } +// signatureInstrumented is the optional capability a driver token service implements to hand the +// signature service the observer denials are reported to and the gate that produces them. It is +// probed rather than required so that a driver, or a test double, that installs no policy keeps +// working unchanged. +type signatureInstrumented interface { + // SignatureObserver returns the observer denied operations are reported to. + SignatureObserver() sigobserve.Observer + // SignatureGate returns the gate consulted before each operation, or nil for none. + SignatureGate() SignatureGate +} + +// signatureServiceOptions derives the signature service's options from the driver token service. +func signatureServiceOptions(tms driver.TokenManagerService) []SignatureServiceOption { + instrumented, ok := tms.(signatureInstrumented) + if !ok { + return nil + } + + gate := instrumented.SignatureGate() + if gate == nil { + // Without a gate there is nothing to report: the operations themselves are instrumented + // at the identity provider and the deserializer, not here. + return nil + } + + return []SignatureServiceOption{ + WithSignatureObserver(instrumented.SignatureObserver()), + WithSignatureGate(gate), + } +} + // GetManagementService retrieves a TMS instance using the provided options. // Returns the default TMS if no options are specified. // Options: WithNetwork, WithChannel, WithNamespace, WithPublicParameterFetcher, WithTMS, WithTMSID