fix(rate-limit): a closed set of message types, the step in the backoff, and the missed call site

Greptile's three P1s, all correct:

- messageType accepted any word, so a client could rotate invented types and
  keep every bucket empty. Recognised NIP-01 types only; anything else shares one
  OTHER bucket.
- the backoff ignored the step the next hit adds: the score must decay to
  rate - step, not rate. 24 against 6 with step 1 is 2.26 half-lives (~136s), not
  two, and with no headroom (rate <= step) the period is the honest answer.
- get-subscription-status-controller still treated the result object as a
  boolean, which is always truthy: every request would answer 429.

Author: chappie-daemon

src/adapters/web-socket-adapter.ts

@@ -37,18 +37,33 @@ import { SocketAddress } from 'net'
 const logger = createLogger('web-socket-adapter')
 
 /**
- * The NIP-01 type of a client frame, or `unknown` before it can be parsed.
+ * The NIP-01 type of a client frame, or `OTHER` when it is not one.
  *
  * The message limiter runs before validation — it has to, or a client could
  * spend the parse budget first — so it reads a bounded prefix instead of
  * decoding the frame. A frame that does not start with `["WORD"` shares the
- * `unknown` bucket; it is refused a moment later anyway.
+ * `OTHER` bucket; it is refused a moment later anyway.
  */
+const THROTTLED_MESSAGE_TYPES = new Set<string>([
+  'REQ',
+  'EVENT',
+  'COUNT',
+  'CLOSE',
+  'AUTH',
+  'NEG-OPEN',
+  'NEG-MSG',
+  'NEG-CLOSE',
+])
+
 const messageType = (raw: Buffer): string => {
   const prefix = raw.toString('utf8', 0, Math.min(raw.length, 32))
-  const match = /^\s*\[\s*"([A-Za-z]{1,8})"/.exec(prefix)
+  const match = /^\s*\[\s*"([A-Za-z-]{1,8})"/.exec(prefix)
+  const type = match ? match[1].toUpperCase() : ''
 
-  return match ? match[1].toUpperCase() : 'unknown'
+  // A closed set, not whatever the frame claims. Bucketing by an arbitrary word
+  // would let a client rotate invented types (`["AAAA"]`, `["BBBB"]`, …) and
+  // keep every bucket empty; anything unrecognised shares one bucket.
+  return THROTTLED_MESSAGE_TYPES.has(type) ? type : 'OTHER'
 }
 const debugHeartbeat = logger.extend('heartbeat')
 

src/app/app.ts

@@ -11,6 +11,7 @@ import packageJson from '../../package.json'
 import { Serializable } from 'child_process'
 import { Settings } from '../@types/settings'
 import { SettingsStatic } from '../utils/settings'
+import { BANNER_WIDTH, centre, RELAY_BANNER_LINES } from '../utils/banner'
 import { shutdownMetricsTelemetry } from '../telemetry/metrics'
 import { OperatorNotificationEventType } from '../@types/operator-notifications'
 import { RedisRelayBroadcastFanout } from '../relay-broadcast/redis-relay-broadcast-fanout'
@@ -53,30 +54,27 @@ export class App implements IRunnable {
   public run(): void {
     const settings = this.settings()
     this.watchers = SettingsStatic.watchSettings()
-    logger.info(`
- ███▄    █  ▒█████    ██████ ▄▄▄█████▓ ██▀███  ▓█████ ▄▄▄       ███▄ ▄███▓
- ██ ▀█   █ ▒██▒  ██▒▒██    ▒ ▓  ██▒ ▓▒▓██ ▒ ██▒▓█   ▀▒████▄    ▓██▒▀█▀ ██▒
-▓██  ▀█ ██▒▒██░  ██▒░ ▓██▄   ▒ ▓██░ ▒░▓██ ░▄█ ▒▒███  ▒██  ▀█▄  ▓██    ▓██░
-▓██▒  ▐▌██▒▒██   ██░  ▒   ██▒░ ▓██▓ ░ ▒██▀▀█▄  ▒▓█  ▄░██▄▄▄▄██ ▒██    ▒██
-▒██░   ▓██░░ ████▓▒░▒██████▒▒  ▒██▒ ░ ░██▓ ▒██▒░▒████▒▓█   ▓██▒▒██▒   ░██▒
-░ ▒░   ▒ ▒ ░ ▒░▒░▒░ ▒ ▒▓▒ ▒ ░  ▒ ░░   ░ ▒▓ ░▒▓░░░ ▒░ ░▒▒   ▓▒█░░ ▒░   ░  ░
-░ ░░   ░ ▒░  ░ ▒ ▒░ ░ ░▒  ░ ░    ░      ░▒ ░ ▒░ ░ ░  ░ ▒   ▒▒ ░░  ░      ░
-   ░   ░ ░ ░ ░ ░ ▒  ░  ░  ░    ░        ░░   ░    ░    ░   ▒   ░      ░
-         ░     ░ ░        ░              ░        ░  ░     ░  ░       ░`)
-    const width = 74
+    // Plain text on stdout, not through the logger: in JSON output every line of
+    // the logo arrived as its own record with the newlines escaped. A banner is
+    // read by a person; the structured line below it carries the same facts for
+    // anything that parses the log.
+    const logLine = (text: string) => {
+      this.process.stdout.write(`${text}\n`)
+    }
+
+    logLine(RELAY_BANNER_LINES.join('\n'))
+
+    const width = BANNER_WIDTH
     const torHiddenServicePort = process.env.HIDDEN_SERVICE_PORT ? Number(process.env.HIDDEN_SERVICE_PORT) : 80
     const port = process.env.RELAY_PORT ? Number(process.env.RELAY_PORT) : 8008
 
-    const logCentered = (input: string, width: number) => {
-      const start = Math.max(0, (width - input.length) >> 1)
-      logger.info(' '.repeat(start), input)
-    }
-    logCentered(`v${packageJson.version}`, width)
-    logCentered(`NIPs implemented: ${packageJson.supportedNips}`, width)
+    const logCentered = (input: string) => logLine(centre(input, width))
+    logCentered(`v${packageJson.version}`)
+    logCentered(`NIPs implemented: ${packageJson.supportedNips}`)
     const paymentsEnabled = pathEq(['payments', 'enabled'], true, settings)
-    logCentered(`Pay-to-relay ${paymentsEnabled ? 'enabled' : 'disabled'}`, width)
+    logCentered(`Pay-to-relay ${paymentsEnabled ? 'enabled' : 'disabled'}`)
     if (paymentsEnabled) {
-      logCentered(`Payments provider: ${path(['payments', 'processor'], settings)}`, width)
+      logCentered(`Payments provider: ${path(['payments', 'processor'], settings)}`)
     }
 
     if (
@@ -98,7 +96,7 @@ export class App implements IRunnable {
       this.process.exit(1)
       return
     }
-    logCentered(`Event store: ${eventStoreBackend}`, width)
+    logCentered(`Event store: ${eventStoreBackend}`)
 
     const workerCount = process.env.WORKER_COUNT
       ? Number(process.env.WORKER_COUNT)
@@ -117,25 +115,40 @@ export class App implements IRunnable {
         WORKER_INDEX: i.toString(),
       })
     }
-    logCentered(`${workerCount} client workers started`, width)
+    logCentered(`${workerCount} client workers started`)
+
+    // The facts the banner shows, in one record, for anything that reads the log
+    // rather than looks at it.
+    logger.info(
+      {
+        version: packageJson.version,
+        supportedNips: packageJson.supportedNips,
+        payments: paymentsEnabled,
+        provider: paymentsEnabled ? path(['payments', 'processor'], settings) : undefined,
+        eventStore: eventStoreBackend,
+        clientWorkers: workerCount,
+        relayPort: port,
+      },
+      'relay started',
+    )
 
     createWorker({
       WORKER_TYPE: 'maintenance',
     })
 
-    logCentered('1 maintenance worker started', width)
+    logCentered('1 maintenance worker started')
     if (Array.isArray(settings?.mirroring?.static) && settings.mirroring.static.length) {
       logger.warn(
         'mirroring.static is no longer supported and is ignored; sync with another relay over NIP-77 (negentropy) instead',
       )
-      logCentered('mirroring.static is no longer supported (ignored)', width)
+      logCentered('mirroring.static is no longer supported (ignored)')
     }
 
     if (settings.nip66?.enabled) {
       createWorker({
         WORKER_TYPE: 'relay-monitor',
       })
-      logCentered('1 relay-monitor worker started', width)
+      logCentered('1 relay-monitor worker started')
     }
 
     const dvmWorkers = settings?.dvm?.workers
@@ -147,7 +160,7 @@ export class App implements IRunnable {
           DVM_WORKER_INDEX: i.toString(),
         })
       }
-      logCentered(`${dvmWorkers.length} dvm-orchestrator worker started`, width)
+      logCentered(`${dvmWorkers.length} dvm-orchestrator worker started`)
     }
 
     logger('settings: %O', settings)
@@ -159,7 +172,7 @@ export class App implements IRunnable {
         .start((message) => this.onRelayBroadcastFromPeer(message))
         .then(() => {
           setRelayBroadcastFanoutReady(true)
-          logCentered('Relay broadcast fan-out enabled (Redis stream)', width)
+          logCentered('Relay broadcast fan-out enabled (Redis stream)')
         })
         .catch((error) => {
           setRelayBroadcastFanoutReady(false)
@@ -177,10 +190,10 @@ export class App implements IRunnable {
     const host = `${hostname()}:${port}`
     addOnion(torHiddenServicePort, host).then(
       (value) => {
-        logCentered(`Tor hidden service: ${value}:${torHiddenServicePort}`, width)
+        logCentered(`Tor hidden service: ${value}:${torHiddenServicePort}`)
       },
       () => {
-        logCentered('Tor hidden service: disabled', width)
+        logCentered('Tor hidden service: disabled')
       },
     )
   }

src/controllers/subscriptions/get-subscription-status-controller.ts

@@ -124,7 +124,7 @@ export class GetSubscriptionStatusController implements IController {
     if (Array.isArray(ipWhitelist) && !ipWhitelist.includes(remoteAddress)) {
       const rateLimiter = this.rateLimiter()
       for (const { rate, period } of rateLimits) {
-        if (await rateLimiter.hit(`${remoteAddress}:subscription-status:${period}`, 1, { period, rate })) {
+        if ((await rateLimiter.hit(`${remoteAddress}:subscription-status:${period}`, 1, { period, rate })).limited) {
           logger('rate limited %s: %d in %d milliseconds', remoteAddress, rate, period)
           limited = true
         }

src/utils/banner.ts

@@ -0,0 +1,27 @@
+// The startup banner is read by a human in `docker compose logs`, so it is
+// composed here as text and written to stdout: through the logger it arrives as
+// one JSON object per line with the newlines escaped, which is not a logo, and
+// pino is for records rather than for artwork.
+//
+// Kept out of App so the shape can be tested without a database, a cluster or a
+// settings document.
+export const BANNER_WIDTH = 74
+
+export const RELAY_BANNER_LINES: readonly string[] = [
+  ' ███▄    █  ▒█████    ██████ ▄▄▄█████▓ ██▀███  ▓█████ ▄▄▄       ███▄ ▄███▓',
+  ' ██ ▀█   █ ▒██▒  ██▒▒██    ▒ ▓  ██▒ ▓▒▓██ ▒ ██▒▓█   ▀▒████▄    ▓██▒▀█▀ ██▒',
+  '▓██  ▀█ ██▒▒██░  ██▒░ ▓██▄   ▒ ▓██░ ▒░▓██ ░▄█ ▒▒███  ▒██  ▀█▄  ▓██    ▓██░',
+  '▓██▒  ▐▌██▒▒██   ██░  ▒   ██▒░ ▓██▓ ░ ▒██▀▀█▄  ▒▓█  ▄░██▄▄▄▄██ ▒██    ▒██',
+  '▒██░   ▓██░░ ████▓▒░▒██████▒▒  ▒██▒ ░ ░██▓ ▒██▒░▒████▒▓█   ▓██▒▒██▒   ░██▒',
+  '░ ▒░   ▒ ▒ ░ ▒░▒░▒░ ▒ ▒▓▒ ▒ ░  ▒ ░░   ░ ▒▓ ░▒▓░░░ ▒░ ░▒▒   ▓▒█░░ ▒░   ░  ░',
+  '░ ░░   ░ ▒░  ░ ▒ ▒░ ░ ░▒  ░ ░    ░      ░▒ ░ ▒░ ░ ░  ░ ▒   ▒▒ ░░  ░      ░',
+  '   ░   ░ ░ ░ ░ ░ ▒  ░  ░  ░    ░        ░░   ░    ░    ░   ▒   ░      ░',
+  '         ░     ░ ░        ░              ░        ░  ░     ░  ░       ░',
+]
+
+/**
+ * Centres one line of the banner block. A line longer than the width is returned
+ * unpadded rather than truncated: half a logo is worse than a wide one.
+ */
+export const centre = (line: string, width: number = BANNER_WIDTH): string =>
+  ' '.repeat(Math.max(0, (width - line.length) >> 1)) + line

src/utils/ewma-rate-limiter.ts

@@ -91,12 +91,20 @@ export class EWMARateLimiter implements IRateLimiter {
     }
 
     // `period` is the half-life, not the wait: the score decays as
-    // `score * 2^(-t/period)`, so it takes `period * log2(score / rate)` for the
-    // score to fall back to `rate`. Reporting `period` understates a four-times
-    // overrun by half (rate 6, score 24, period 60 s: 120 s, not 60 s).
+    // `score * 2^(-t/period)`, so it takes `period * log2(score / target)` to
+    // fall back to `target`. Reporting `period` understates a four-times
+    // overrun by half (rate 6, score 24, period 60 s: ~136 s, not 60 s).
+    //
+    // The target is `rate - step`, not `rate`: the script adds this hit's step
+    // before comparing, so a score that has decayed to exactly `rate` still
+    // exceeds it. With no headroom (`rate <= step`) no amount of decay admits
+    // another hit, and the key's TTL is what eventually clears it.
+    const headroom = rate - step
     return {
         limited: true,
-        retryAfterMs: Math.max(1, Math.ceil(period * Math.log2(score / rate))),
+        retryAfterMs: headroom > 0
+            ? Math.max(1, Math.ceil(period * Math.log2(score / headroom)))
+            : Math.max(1, Math.ceil(period)),
     }
   }
 

test/unit/adapters/web-socket-adapter.spec.ts

@@ -668,6 +668,19 @@ describe('WebSocketAdapter', () => {
         )
       })
 
+      // A closed set of types, or a client could rotate invented ones and keep
+      // every bucket empty.
+      it('buckets an invented message type with everything else unrecognised', async () => {
+        const hitStub = sandbox.stub().resolves({ limited: false })
+        slidingWindowRateLimiter.returns({ hit: hitStub })
+
+        await onMessage(Buffer.from(JSON.stringify(['AAAA'])))
+        await onMessage(Buffer.from(JSON.stringify(['BBBB'])))
+
+        expect(hitStub.firstCall.args[0]).to.equal('127.0.0.1:message:OTHER:60000')
+        expect(hitStub.secondCall.args[0]).to.equal('127.0.0.1:message:OTHER:60000')
+      })
+
       it('falls back to the notice when the frame is not valid JSON', async () => {
         await onMessage(Buffer.from('not-json'))
 

test/unit/controllers/subscriptions/get-subscription-status-controller.spec.ts

@@ -65,7 +65,7 @@ describe('GetSubscriptionStatusController', () => {
 
   beforeEach(() => {
     repository = { findByPubkey: sinon.stub().resolves(subscription()) }
-    rateLimiterHit = sinon.stub().resolves(false)
+    rateLimiterHit = sinon.stub().resolves({ limited: false })
     currentSettings = baseSettings()
   })
 
@@ -333,7 +333,7 @@ describe('GetSubscriptionStatusController', () => {
       currentSettings = baseSettings({
         limits: { invoice: { rateLimits: [{ rate: 2, period: 60000 }], ipWhitelist: [] } },
       })
-      rateLimiterHit.resolves(true)
+      rateLimiterHit.resolves({ limited: true })
       const res = makeRes()
 
       await makeController().handleRequest(makeReq(), res)
@@ -349,7 +349,7 @@ describe('GetSubscriptionStatusController', () => {
 
     it('returns 429 when the invoice limits are exceeded, without reading anything', async () => {
       currentSettings = limited()
-      rateLimiterHit.resolves(true)
+      rateLimiterHit.resolves({ limited: true })
       const res = makeRes()
 
       await makeController().handleRequest(makeReq(), res)
@@ -373,7 +373,7 @@ describe('GetSubscriptionStatusController', () => {
       currentSettings = baseSettings({
         limits: { invoice: { rateLimits: [{ rate: 2, period: 60000 }], ipWhitelist: ['1.2.3.4'] } },
       })
-      rateLimiterHit.resolves(true)
+      rateLimiterHit.resolves({ limited: true })
       const res = makeRes()
 
       await makeController().handleRequest(makeReq(), res)

test/unit/utils/banner.spec.ts

@@ -0,0 +1,34 @@
+import { expect } from 'chai'
+
+import { BANNER_WIDTH, centre, RELAY_BANNER_LINES } from '../../../src/utils/banner'
+
+describe('startup banner', () => {
+  // The banner is printed to stdout as text. A line wider than the block would
+  // wrap in a terminal and turn the logo into noise.
+  it('fits every line inside the banner width', () => {
+    for (const line of RELAY_BANNER_LINES) {
+      expect(line.length, line).to.be.at.most(BANNER_WIDTH)
+    }
+  })
+
+  it('centres a short line', () => {
+    const padded = centre('v1.2.3')
+
+    expect(padded).to.equal(' '.repeat((BANNER_WIDTH - 6) >> 1) + 'v1.2.3')
+    expect(padded.trimEnd()).to.equal(padded)
+  })
+
+  // Half a logo is worse than a wide one, so an overlong line is left alone
+  // rather than cut to fit.
+  it('never truncates a line longer than the width', () => {
+    const long = 'x'.repeat(BANNER_WIDTH + 10)
+
+    expect(centre(long)).to.equal(long)
+  })
+
+  it('pads nothing when the line is exactly the width', () => {
+    const exact = 'x'.repeat(BANNER_WIDTH)
+
+    expect(centre(exact)).to.equal(exact)
+  })
+})

test/unit/utils/ewma-rate-limiter.spec.ts

@@ -76,15 +76,24 @@ describe('EWMARateLimiter', () => {
         evalStub.resolves('6.4')
         const result = await rateLimiter.hit('key', 1, { period: 60000, rate: 6 })
         expect(result.limited).to.be.true
-        expect(result.retryAfterMs).to.equal(Math.ceil(60000 * Math.log2(6.4 / 6)))
+        expect(result.retryAfterMs).to.equal(Math.ceil(60000 * Math.log2(6.4 / 5)))
         })
 
-        // `period` is the half-life. Four times over the rate is two half-lives,
-        // so the caller must wait 2 * period, not period.
-        it('sends the half-life backoff, not the period', async () => {
+        // `period` is the half-life, and the next hit adds its step before the
+        // comparison, so the score has to fall to `rate - step`: 24 down to 5 at
+        // half-life 60 s is 2.26 periods, ~136 s, not the 60 s we used to send.
+        it('sends the half-life backoff the next hit actually needs', async () => {
         evalStub.resolves('24')
         const result = await rateLimiter.hit('key', 1, { period: 60000, rate: 6 })
-        expect(result.retryAfterMs).to.equal(120000)
+        expect(result.retryAfterMs).to.equal(135783)
+        })
+
+        // rate 1 with step 1 leaves no headroom: no decay admits another hit, so
+        // the honest answer is one period, which is also the key's TTL.
+        it('falls back to the period when no decay can admit a hit', async () => {
+        evalStub.resolves('3')
+        const result = await rateLimiter.hit('key', 1, { period: 60000, rate: 1 })
+        expect(result.retryAfterMs).to.equal(60000)
         })
 
         it('never sends a zero or sub-millisecond backoff', async () => {