Observers

MeoCord 4.1 · The request pipeline · page 30 of 41 · since 4.1.0

Hear about every call MeoCord dispatches, as it starts and once it has settled, for metrics, audit logs and traces.

You'll learn

Record every call and how it ended with an observer
Read a call's outcome, duration and answer
Trace a call from start to finish, and pair it with a span inside the handler

Before this

An observer is told about every call MeoCord dispatches: commands, components, modals, autocomplete, message, reaction and event handlers, and interactions no handler matches. It hears about each once it has settled, with how it ended and how long it took, and optionally as it starts.

When to use it

Use an observer for metrics, audit logs and traces: anything that must see every outcome. No other stage does. Guards run before anything is decided, interceptors never see a call a guard denied or an autocomplete, and filters see only errors.

An observer only watches. To change a call, such as timing the handler and logging inside it, use an interceptor; to answer an error, an exception filter.

Example

An observer implements onSettled, which receives the call's ExecutionContext and how it ended:

observers/metrics.observer.ts

import { type ExecutionContext } from 'meocord/common'
import { Observer } from 'meocord/decorator'
import { type DispatchObserver, type DispatchResult } from 'meocord/interface'
import { MetricsService } from '@src/services/metrics.service'

// One instance, resolved from the container, is told about every call once it has settled
@Observer()
export class MetricsObserver implements DispatchObserver {
  constructor(private readonly metrics: MetricsService) {}

  onSettled(context: ExecutionContext, { outcome, durationMs }: DispatchResult) {
    // An interaction no handler matched has no handler name
    this.metrics.record(context.getType(), context.getHandlerName() ?? 'unrouted', outcome, durationMs)
  }
}

List it in @MeoCord({ observers }):

app-with-observers.ts

import { GatewayIntentBits } from 'discord.js'
import { MeoCord } from 'meocord/decorator'
import { ModerationSlashController } from '@src/controllers/slash/moderation.slash.controller'
import { HandlerSpanInterceptor } from '@src/interceptors/handler-span.interceptor'
import { AuditObserver } from '@src/observers/audit.observer'
import { CallSpanObserver } from '@src/observers/call-span.observer'
import { MetricsObserver } from '@src/observers/metrics.observer'

@MeoCord({
  controllers: [ModerationSlashController],
  interceptors: [HandlerSpanInterceptor],
  // Told in this order, each on its own: one that throws is logged, and the next is still told
  observers: [CallSpanObserver, MetricsObserver, AuditObserver],
  clientOptions: { intents: [GatewayIntentBits.Guilds] },
})
export default class App {}

Every call is now recorded with its type, its handler, its outcome and how long it took, the denied and failed ones included.

How it works

An observer frames the whole call. onStart, which is optional, hears about it as it begins, before @Defer and the guards. onSettled hears about it once it has settled and been answered, by the handler, a filter or the fallback. How a call runs shows the stages in between.

The call waits for neither method, so a slow observer never delays a handler. One that throws is logged through Logger, and the other observers still run. They're told one after another, in the order observers lists them.

An observer is a class marked @Observer() that implements DispatchObserver. One instance is resolved from the container, so it injects services, and its onReady and onShutdown lifecycle hooks run in dependency order with the rest: an exporter flushes what it buffered in onShutdown. It can't inject ExecutionContext; each call's context is passed in.

What an observer is told

onSettled's second argument, a DispatchResult, holds:

Field	What it is
`outcome`	How the call ended; see below.
`startedAt`	When dispatch received the call, in milliseconds since the Unix epoch.
`durationMs`	From dispatch until the filters and the fallback had answered.
`deniedBy`	The guard class that denied the call, whether it returned `false` or threw `GuardDeniedError`.
`response`	For an interaction, where its answer stood: `'replied'`, `'deferred'` (never followed up) or `'unanswered'`.
`error`	The error the call ended with, when it ended with one.
`handled`	Whether an exception filter or the built-in fallback answered the error; `false` without one.

The outcome is one of:

Outcome	When
`'ran'`	The call settled without an error, an interceptor that answered without the handler included.
`'denied'`	A guard returned `false` (no `error`), or `GuardDeniedError` was thrown; `deniedBy` names the guard, unless the handler threw it itself.
`'cooldown'`	A cooldown refused it with `CooldownError`.
`'invalid'`	Validation refused its input with `ValidationError`, or a message named a command it doesn't fit, with `MessageUsageError`.
`'refused'`	A `UserError` told the user what to fix: their mistake, not a fault of the bot.
`'error'`	Anything else was thrown, by the handler, a pipe, an interceptor or a guard.
`'not-found'`	No handler matches the interaction and nothing else answered it.

The context is the one the call's stages saw, so getType(), getHandlerName(), getArgs() and getHandlerParams() read the same values. For an interaction no handler matched, it has no controller or handler.

What is reported

Every interaction, the ones no handler matches included; those get onSettled only. A button, select menu or modal no route takes that another listener answers, such as a collector, is that listener's to report, and isn't told.
Every message and reaction a handler runs for, and every event handler call.
A message that names a command but doesn't fit it, such as a word of the wrong type, as 'invalid'. A parent command's words alone, answered with its subcommands, reach no handler, and are reported without one.
Not a message no handler matches otherwise: most of a server's traffic would reach the observers for nothing.

@Observer({ types: ['interaction'] }) limits an observer to those calls, as ExecutionContext.getType() reports them; an autocomplete's type is 'autocomplete'.

An audit log

This observer writes each refused interaction to an audit log, with the guard that refused it, and warns when a handler deferred and never answered, which leaves the user on "thinking…":

observers/audit.observer.ts

import { type BaseInteraction } from 'discord.js'
import { type ExecutionContext, Logger } from 'meocord/common'
import { Observer } from 'meocord/decorator'
import { type DispatchObserver, type DispatchResult } from 'meocord/interface'
import { RefusalLog } from '@src/services/refusal-log.service'

// Told only about interactions: commands, components and modals; autocomplete is a type of its own
@Observer({ types: ['interaction'] })
export class AuditObserver implements DispatchObserver {
  private readonly logger = new Logger(AuditObserver.name)

  constructor(private readonly refusals: RefusalLog) {}

  async onSettled(context: ExecutionContext, { outcome, deniedBy, response, startedAt }: DispatchResult) {
    const interaction = context.getArgs()[0] as BaseInteraction
    const handler = context.getHandlerName() ?? 'unrouted'

    // A handler that deferred and never followed up leaves the user on "thinking…"
    if (response === 'deferred') this.logger.warn(`${handler} deferred and never answered`)

    // Only what was refused: a denied, rate-limited or invalid call, or one no handler matched
    if (outcome === 'ran' || outcome === 'error') return
    this.refusals.write({
      user: interaction.user.id,
      handler,
      outcome,
      deniedBy: deniedBy?.name,
      at: new Date(startedAt),
    })
  }
}

Tracing a call

onSettled receives the same context object as onStart for the same call, so a WeakMap pairs them. That gives a span for every call that reaches a handler, a denied one included. An interaction no handler matched gets onSettled only, so it has no span:

observers/call-span.observer.ts

import { type Span, SpanStatusCode, trace } from '@opentelemetry/api'
import { type ExecutionContext } from 'meocord/common'
import { Observer } from 'meocord/decorator'
import { type DispatchObserver, type DispatchResult } from 'meocord/interface'

const tracer = trace.getTracer('bot')

// The call's own span, from the moment it arrives, whatever the outcome
@Observer()
export class CallSpanObserver implements DispatchObserver {
  // onStart and onSettled for one call receive the same context object
  private readonly spans = new WeakMap<ExecutionContext, Span>()

  onStart(context: ExecutionContext) {
    this.spans.set(context, tracer.startSpan(`${context.getType()} ${context.getHandlerName() ?? 'unrouted'}`))
  }

  onSettled(context: ExecutionContext, { outcome, deniedBy, error }: DispatchResult) {
    const span = this.spans.get(context)
    if (!span) return
    span.setAttribute('meocord.outcome', outcome)
    if (deniedBy) span.setAttribute('meocord.denied_by', deniedBy.name)
    if (outcome === 'error') span.setStatus({ code: SpanStatusCode.ERROR, message: String(error) })
    span.end()
  }
}

An observer sees the call from outside, though. A span for work inside the handler, such as a database query nested under the command, comes from an interceptor, which runs within the call and can make its span the active one:

interceptors/handler-span.interceptor.ts

import { trace } from '@opentelemetry/api'
import { type ExecutionContext } from 'meocord/common'
import { Interceptor } from 'meocord/decorator'
import { type CallHandler, type InterceptorInterface } from 'meocord/interface'

const tracer = trace.getTracer('bot')

// The handler's span, active while it runs, so the spans it starts, a database query say, nest under it
@Interceptor()
export class HandlerSpanInterceptor implements InterceptorInterface {
  async intercept(context: ExecutionContext, next: CallHandler): Promise<unknown> {
    return tracer.startActiveSpan(`handler ${context.getHandlerName()}`, async span => {
      try {
        return await next.handle()
      } finally {
        span.end()
      }
    })
  }
}

Register both: the observer in observers, the interceptor in interceptors. Without an OpenTelemetry SDK set up, @opentelemetry/api records nothing, so the two cost nothing until the bot exports traces.

Testing

invoke and emit wait for the module's observers before they resolve, so a test sees what they were told. The testing module takes an app's observers, and observers of its own. inspectHandler(Controller, 'method', { app }) lists the app's observers in observers, in the order they are told:

observers/audit.observer.spec.ts

describe('observers', () => {
  // The app's observers, and its interceptors, apply as they do in the bot
  const module = MeoCordTestingModule.create({ app: App, controllers: [ModerationSlashController] }).compile()

  it('are told about a call before invoke resolves', async () => {
    const elsewhere = createMockInteraction(ChatInputCommandInteraction, { channelId: '222222222222222222' })

    await expect(module.invoke(ModerationSlashController, 'trade', elsewhere)).resolves.toEqual({ ran: false })

    expect(module.get(MetricsService).count('interaction', 'trade', 'denied')).toBe(1)
    expect(module.get(RefusalLog).entries).toEqual([
      {
        user: elsewhere.user.id,
        handler: 'trade',
        outcome: 'denied',
        deniedBy: ChannelGuard.name,
        at: expect.any(Date),
      },
    ])
  })

  it('are listed for each handler, in order', () => {
    expect(inspectHandler(ModerationSlashController, 'trade', { app: App }).observers).toEqual([
      CallSpanObserver,
      MetricsObserver,
      AuditObserver,
    ])
  })
})

Generate an observer with npx meocord g ob <name>: it logs each call's type, handler, outcome and duration, to start from.

Gotchas

An observer can't change a call. It runs outside it, and nothing it returns or throws reaches the user.
@Observer({ types: [] }) throws as the decorator applies. Leave types out to hear every call.
A message nobody handles isn't reported. Count those in an @On('messageCreate') handler if you need them.

Next steps

Custom decorators: name a set of stages once and reuse it.
Testing recipes: assert on what your observers were told.
Deployment: export metrics and traces from a running bot.