Logger and Timing

Overview

The logger middleware intercepts incoming requests, tracks elapsed execution time, and records access logs via configurable print functions. Sources: src/middleware/logger/index.ts:50-94

It applies terminal styling and humanized duration formatting based on dynamic runtime environment color detection. Sources: src/middleware/logger/index.ts:15-46, src/utils/color.ts:36-55

Simultaneously, the timing middleware leverages context variable augmentation to instrument operational metrics and compile them into standard Server-Timing HTTP response headers. Sources: src/middleware/timing/timing.ts:10-202, src/middleware/timing/index.ts:1-7

Logger middleware architecture and dispatch

Interception and Request Lifecycle

The logger middleware returns an asynchronous MiddlewareHandler that intercepts every incoming request dispatched through the routing layer. Upon invocation, it extracts the HTTP method and URL from the request object (c.req), isolates the relative request path by locating the first forward slash following the protocol scheme, and immediately logs the incoming request using the LogPrefix.Incoming prefix (<--).

Copyexport const logger = (fn: PrintFunc = console.log): MiddlewareHandler => {
  return async function logger(c, next) {
    const { method, url } = c.req
 
    const path = url.slice(url.indexOf('/', 8))
 
    await log(fn, LogPrefix.Incoming, method, path)
 
    const start = Date.now()
 
    await next()
 
    await log(fn, LogPrefix.Outgoing, method, path, c.res.status, time(start))
  }
}

Sources: src/middleware/logger/index.ts:81-94

Access Logging and Prefixes

The core logging dispatcher log formats output depending on whether the log entry represents an incoming request or an outgoing response. It accepts an optional custom print function fn which defaults to console.log.

Copyenum LogPrefix {
  Outgoing = '-->',
  Incoming = '<--',
  Error = 'xxx',
}
 
async function log(
  fn: PrintFunc,
  prefix: string,
  method: string,
  path: string,
  status: number = 0,
  elapsed?: string
) {
  const out =
    prefix === LogPrefix.Incoming
      ? `${prefix} ${method} ${path}`
      : `${prefix} ${method} ${path} ${await colorStatus(status)} ${elapsed}`
  fn(out)
}

Sources: src/middleware/logger/index.ts:9-13, src/middleware/logger/index.ts:50-63

Colorized status codes and formatting

ANSI terminal styling and status colors

The colorStatus function evaluates HTTP response status codes and wraps them in ANSI escape sequences when terminal colors are enabled. It divides the numeric status by 100 and floors the result to determine the response category. Success codes, redirects, client errors, and server errors each map to a distinct color code. If color support is disabled, the raw status number is returned as a plain string. Sources: src/middleware/logger/index.ts:28-46

Copyconst colorStatus = async (status: number) => {
  const colorEnabled = await getColorEnabledAsync()
  if (colorEnabled) {
    switch ((status / 100) | 0) {
      case 5: // red = error
        return `\x1b[31m${status}\x1b[0m`
      case 4: // yellow = warning
        return `\x1b[33m${status}\x1b[0m`
      case 3: // cyan = redirect
        return `\x1b[36m${status}\x1b[0m`
      case 2: // green = success
        return `\x1b[32m${status}\x1b[0m`
    }
  }
  return `${status}`
}

Sources: src/middleware/logger/index.ts:28-46

Dynamic runtime color detection

Runtime color detection is handled through a structured sequence starting at the logger middleware and resolving through log, colorStatus, getColorEnabledAsync, and getColorEnabled. The asynchronous getColorEnabledAsync checks if the execution environment is running on Cloudflare Workers by inspecting navigator.userAgent. If true, it dynamically imports cloudflare:workers to check whether the NO_COLOR environment variable is present in the worker environment bindings. Otherwise, it delegates to the synchronous getColorEnabled helper. Sources: src/utils/color.ts:36-55

The synchronous getColorEnabled function inspects globalThis for Deno and process globals. It checks Deno.noColor if present, or checks whether NO_COLOR exists within process.env. If either flag is detected, color output is disabled. Sources: src/utils/color.ts:14-27

Copyexport function getColorEnabled(): boolean {
  const { process, Deno } = globalThis as any
 
  const isNoColor =
    typeof Deno?.noColor === 'boolean'
      ? (Deno.noColor as boolean)
      : process !== undefined
        ? 'NO_COLOR' in process?.env
        : false
 
  return !isNoColor
}

Sources: src/utils/color.ts:14-27

Humanized duration formatting

Elapsed request execution times are processed by the time and humanize utilities. The time function computes the difference between the current timestamp and the start time. If the elapsed delta is below 1,000 milliseconds, it formats the value with a trailing ms unit. Otherwise, it rounds the delta into seconds with a trailing s unit. Sources: src/middleware/logger/index.ts:23-26

The humanize helper splits and formats large digit sequences by inserting comma delimiters every three digits using regular expression matching, joining the resulting parts with periods. Sources: src/middleware/logger/index.ts:15-21

Copyconst humanize = (times: string[]) => {
  const [delimiter, separator] = [',', '.']
 
  const orderTimes = times.map((v) => v.replace(/(\d)(?=(\d\d\d)+(?!\d))/g, '$1' + delimiter))
 
  return orderTimes.join(separator)
}
 
const time = (start: number) => {
  const delta = Date.now() - start
  return humanize([delta < 1000 ? delta + 'ms' : Math.round(delta / 1000) + 's'])
}

Sources: src/middleware/logger/index.ts:15-26

Call-Chain Execution Walkthrough for Logger and Color Resolution (Logger -> GetColorEnabled)

When the logger middleware executes a request, it coordinates several functions in a strict sequential call order (logger → log → colorStatus → getColorEnabledAsync → getColorEnabled) to determine and log colorized statuses. The execution flow follows this exact sequence:

1. logger (defined in src/middleware/logger/index.ts:81-94) initiates the request lifecycle, invokes await next(), and then calls log() with outgoing parameters including the response status. Sources: src/middleware/logger/index.ts:81-94
2. log (defined in src/middleware/logger/index.ts:50-63) constructs the log message string, awaiting colorStatus(status) to format the numeric status code. Sources: src/middleware/logger/index.ts:50-63
3. colorStatus (defined in src/middleware/logger/index.ts:28-46) evaluates whether terminal colors are enabled by invoking getColorEnabledAsync(). Sources: src/middleware/logger/index.ts:28-46
4. getColorEnabledAsync (defined in src/utils/color.ts:36-55) checks Cloudflare Workers bindings or delegates directly to getColorEnabled(). Sources: src/utils/color.ts:36-55
5. getColorEnabled (defined in src/utils/color.ts:14-27) inspects Deno.noColor and process.env.NO_COLOR to determine color support status. Sources: src/utils/color.ts:14-27

Sources: src/middleware/logger/index.ts:28-30, src/middleware/logger/index.ts:50-63, src/middleware/logger/index.ts:81-94, src/utils/color.ts:14-27, src/utils/color.ts:36-55

Server-Timing middleware and metrics collection

Public interface and configuration

The timing middleware factory accepts an optional TimingOptions configuration object to control metric collection behavior and response header generation. It exports TimingVariables, which augments the Hono ContextVariableMap interface via module augmentation in src/middleware/timing/index.ts.

Copyinterface TimingOptions {
  total?: boolean
  enabled?: boolean | ((c: Context) => boolean)
  totalDescription?: string
  autoEnd?: boolean
  crossOrigin?: boolean | string | ((c: Context) => boolean | string)
}

Sources: src/middleware/timing/timing.ts:22-28

Copyimport type { TimingVariables } from './timing'
 
export { TimingVariables }
export { timing, setMetric, startTime, endTime, wrapTime } from './timing'
 
declare module '../..' {
  interface ContextVariableMap extends TimingVariables {}
}

Sources: src/middleware/timing/index.ts:1-8

Metric collection lifecycle

The timestamp resolution routine getTime attempts to use high-resolution performance timers via performance.now(), falling back to Date.now() if an error occurs.

Copyconst getTime = (): number => {
  try {
    return performance.now()
  } catch {}
  return Date.now()
}

Sources: src/middleware/timing/timing.ts:30-35

During an incoming request, the middleware initializes an empty headers array and a timers map stored in the context under the 'metric' key. If options.total is enabled, it records a starting entry for 'total'. After awaiting next(), it finalizes the total timer, iterates through any remaining timers if options.autoEnd is active, evaluates whether insertion is enabled, and populates the Server-Timing and Timing-Allow-Origin response headers.

Copyreturn async function timing(c, next) {
  const headers: string[] = []
  const timers = new Map<string, Timer>()
 
  if (c.get('metric')) {
    return await next()
  }
 
  c.set('metric', { headers, timers })
 
  if (options.total) {
    startTime(c, 'total', options.totalDescription)
  }
  await next()
 
  if (options.total) {
    endTime(c, 'total')
  }
 
  if (options.autoEnd) {
    timers.forEach((_, key) => {
      endTime(c, key)
    })
  }
 
  const enabled = typeof options.enabled === 'function' ? options.enabled(c) : options.enabled
 
  if (enabled) {
    c.res.headers.append('Server-Timing', headers.join(','))
 
    const crossOrigin =
      typeof options.crossOrigin === 'function' ? options.crossOrigin(c) : options.crossOrigin
 
    if (crossOrigin) {
      c.res.headers.append(
        'Timing-Allow-Origin',
        typeof crossOrigin === 'string' ? crossOrigin : '*'
      )
    }
  }
}

Sources: src/middleware/timing/timing.ts:85-125

Operational timers and metric instrumentation

Manual duration recording utilities

Instrumenting request handlers relies on explicit helper functions to capture metrics and active timer intervals: setMetric, startTime, and endTime. Each utility verifies that the context contains an initialized 'metric' store; if the middleware has been omitted from the route, a warning message is emitted to the console and execution returns without error.

Copyexport const setMetric: SetMetric = (
  c: Context,
  name: string,
  valueDescription: number | string | undefined,
  description?: string,
  precision?: number
) => {
  const metrics = c.get('metric')
  if (!metrics) {
    console.warn('Metrics not initialized! Please add the `timing()` middleware to this route!')
    return
  }

Sources: src/middleware/timing/timing.ts:149-160

Copyexport const startTime = (c: Context, name: string, description?: string) => {
  const metrics = c.get('metric')
  if (!metrics) {
    console.warn('Metrics not initialized! Please add the `timing()` middleware to this route!')
    return
  }
  metrics.timers.set(name, { description, start: getTime() })
}

Sources: src/middleware/timing/timing.ts:187-194

Copyexport const endTime = (c: Context, name: string, precision?: number) => {
  const metrics = c.get('metric')
  if (!metrics) {
    console.warn('Metrics not initialized! Please add the `timing()` middleware to this route!')
    return
  }
  const timer = metrics.timers.get(name)
  if (!timer) {
    console.warn(`Timer "${name}" does not exist!`)
    return
  }

Sources: src/middleware/timing/timing.ts:208-218

Parameter signatures and metrics formatting

The setMetric function supports overloaded call signatures to handle both numeric duration measurements and value-less metadata flags. When a numeric value is passed, it formats the duration string using a specified precision, defaulting to one decimal place.

Copyinterface SetMetric {
  (c: Context, name: string, value: number, description?: string, precision?: number): void
 
  (c: Context, name: string, description?: string): void
}

Sources: src/middleware/timing/timing.ts:128-132

Copy  if (typeof valueDescription === 'number') {
    const dur = valueDescription.toFixed(precision || 1)
 
    const metric = description ? `${name};dur=${dur};desc="${description}"` : `${name};dur=${dur}`
 
    metrics.headers.push(metric)
  } else {
    // Value-less metric
    const metric = valueDescription ? `${name};desc="${valueDescription}"` : `${name}`
 
    metrics.headers.push(metric)
  }
}

Sources: src/middleware/timing/timing.ts:161-173

Server-Timing response header serialization

Header formatting rules and metric strings

Collected metric names, durations, and optional descriptions are serialized into standard HTTP header values during the final phase of the timing middleware execution. Depending on the input arguments passed to setMetric or recorded by active timers via endTime, the serialization formats metrics as either value-bearing entries or value-less metadata flags.

Copy  if (typeof valueDescription === 'number') {
    const dur = valueDescription.toFixed(precision || 1)
 
    const metric = description ? `${name};dur=${dur};desc="${description}"` : `${name};dur=${dur}`
 
    metrics.headers.push(metric)
  } else {
    // Value-less metric
    const metric = valueDescription ? `${name};desc="${valueDescription}"` : `${name}`
 
    metrics.headers.push(metric)
  }
}

Sources: src/middleware/timing/timing.ts:161-173

Response injection and cross-origin configuration

Once enabled status is verified, accumulated entries in the header array are joined with commas and appended to the response under the Server-Timing header key. If cross-origin reading is configured, a complementary Timing-Allow-Origin header is attached using either the specified string origin or a wildcard *.

Copyconst enabled = typeof options.enabled === 'function' ? options.enabled(c) : options.enabled
 
if (enabled) {
  c.res.headers.append('Server-Timing', headers.join(','))
 
  const crossOrigin =
    typeof options.crossOrigin === 'function' ? options.crossOrigin(c) : options.crossOrigin
 
  if (crossOrigin) {
    c.res.headers.append(
      'Timing-Allow-Origin',
      typeof crossOrigin === 'string' ? crossOrigin : '*'
    )
  }
}

Sources: src/middleware/timing/timing.ts:110-124

Related

• Request ID and Language