How We Built End-to-End Observability for Our Hono + Bun Backend

Flying blind in production is not an option. You ship a bug, users report something vague like "the feed is broken," and you have no request IDs, no timings, no DB query counts — nothing to grep. This is the story of how we went from zero observability to a full structured logging + distributed tracing stack, all feeding into ClickHouse and surfaced through ClickStack.

The Problem

Our backend is a Hono app running on Bun, using Drizzle ORM over PostgreSQL. Early on, logging was whatever a developer felt like console.log-ing at the time. No structure, no correlation, no way to answer:

• Which request triggered this error?
• Who was the user?
• How many DB queries did this endpoint fire?
• Was this a slow query or a slow handler?
• Do the logs for request X match the trace for request X?

We needed to fix all of that without bolting on a heavyweight APM agent.

The Architecture

                      HTTP Request
                             │
                             ▼
                  ┌──────────────────────┐
                  │   otelMiddleware      │  ← Starts OTel span, extracts W3C traceparent
                  │                      │    Stores traceId + spanId on Hono context
                  └──────────┬───────────┘
                             │
                             ▼
                  ┌──────────────────────┐
                  │   httpLogger          │  ← Creates request-scoped Pino logger
                  │                      │    (requestId + traceId + spanId bound)
                  └──────────┬───────────┘
                             │
                             ▼
                  ┌──────────────────────┐
                  │   Route Handlers      │  ← trackedDb wraps Drizzle via Proxy
                  │   + Drizzle ORM       │    Each query → OTel child span
                  └──────────┬───────────┘
                             │
                      ┌──────┴──────┐
                      │             │
                      ▼             ▼
            ┌──────────────┐  ┌──────────────────┐
            │  Pino Logger  │  │  OTel Provider    │
            │               │  │  (BatchProcessor) │
            └──────┬────────┘  └────────┬─────────┘
                   │                    │
            ┌──────▼────────┐  ┌────────▼─────────┐
            │ClickHouse     │  │ClickHouse         │
            │Transport      │  │SpanExporter       │
            │(pino transport│  │(error spans only) │
            │  batched)     │  │   batched         │
            └──────┬────────┘  └────────┬─────────┘
                   │                    │
                   ▼                    ▼
            ┌───────────────────────────────────────┐
            │            ClickHouse                  │
            │  app_logs table   otel_traces table     │
            │       └──── otel_app_logs view ────┘   │
            └───────────────────────────────────────┘
                             │
                             ▼
                       ClickStack UI
                  (logs + trace waterfall)

Three layers:

• Structured logs — Pino, JSON in production, pretty-printed locally. Every log line carries requestId, traceId, spanId, userId.
• Distributed traces — OpenTelemetry SDK, one span per HTTP request + child spans per DB query. Error-only sampling: spans only reach ClickHouse when something went wrong.
• ClickHouse as the single sink for both. An otel_app_logs view maps logs into OTel schema so ClickStack can join logs and traces by traceId.

Layer 1: Structured Logging with Pino

We use pino because it's fast and outputs JSON by default.

Base Logger

The appLogger in src/lib/logger.ts is the singleton. Environment-aware level and transport:

const level = process.env.LOG_LEVEL ?? (process.env.APP_ENV === "production" ? "info" : "debug");
const usePrettyTransport = process.env.APP_ENV === "local";

• local: pretty-printed, human-readable, debug level
• development / production: JSON, no pretty printing, info level (debug in dev)

Pino's redact option walks the log object and replaces matched paths with [Redacted] before serialization — zero-copy, happens in the worker thread. We redact 40+ paths covering passwords, tokens, OTPs, API keys, and financial data:

redact: {
  paths: ["body.password", "headers.authorization", "responseBody.token", ...],
  censor: "[Redacted]",
}

Non-JSON bodies (form data, plain text errors) get regex-based redaction instead since Pino can't walk them as objects. When CLICKHOUSE_URL is set, a second Pino transport target fires alongside pino-pretty (or alone in production). Pino runs transports in a worker thread — ClickHouse writes never block the main event loop.

Request-Scoped Logger

Every request gets a Pino child logger with requestId, userId, traceId, and spanId bound. Once bound, every logger.info() call from that request automatically includes all four fields without any call-site ceremony.

export function createRequestLogger(
  requestId: string,
  userId?: string,
  traceId?: string,
  spanId?: string
): Logger {
  return appLogger.child({ requestId, userId, trace_id: traceId, span_id: spanId });
}

The userId starts as undefined because auth middleware runs after the logger is created. We rebind the child after auth resolves:

// In httpLogger finally block:
const userId = (c.get("user") as { id: string } | undefined)?.id;
if (userId) {
  logger = createRequestLogger(requestId, userId, traceId, spanId);
  c.set("logger", logger);
}

Layer 2: HTTP Logger Middleware

src/middleware/http-logger.ts wraps every request in a try/finally that produces one canonical log line per request. No scattered console.log noise — one structured event with everything in it:

POST /api/v1/feed/posts 200 142ms [user:a3f8c2b1] [req:9d4e12ab] [5 queries, 87ms]

In local mode: rich formatted string for readability. In production: JSON for aggregators. Fields included in the canonical log line:

Slow request detection: requests over 1 second emit a warn instead of info, plus a second detailed event with the full query list. Response body capture: in local, we capture all response bodies. In production, only 4xx/5xx responses — cloned before reading so the original stream is untouched. Large responses (>100KB), streaming (SSE/chunked), and non-JSON/text types are skipped. Health check suppression: /health and /healthz paths skip the middleware entirely.

Layer 3: DB Query Tracking

src/lib/db-tracker.ts wraps the Drizzle db instance with a Proxy to intercept execute() and transaction() calls. No code changes required in route handlers — the tracked db is injected per request via middleware.

return new Proxy(db, {
  get(target, prop) {
    if (prop === "execute") {
      return function (query, ...args) {
        const promise = target.execute(query, ...args);
        return trackQuery("execute", () => promise, queryDescription);
      };
    }
    // ...
  }
}) as Database;

trackQuery does three things:

• Times the query with performance.now()
• Pushes a record into DbMetrics.queries[]
• Starts an OTel child span for the query (auto-parents to the active HTTP span)

Queries over 100ms go into DbMetrics.slowQueries[] and get a db.slow_query = true span attribute. The metrics object is stored on the Hono context and read by httpLogger in its finally block.

Layer 4: OpenTelemetry Tracing

Initialization

src/lib/otel.ts boots a BasicTracerProvider at startup. W3C trace context propagation is registered globally so incoming traceparent headers from mobile clients are automatically picked up:

export function initOtel(): void {
  if (!process.env.CLICKHOUSE_URL) return; // no-op if not configured

  const exporter = new ClickHouseSpanExporter();
  provider = new BasicTracerProvider({
    resource: resourceFromAttributes({ [ATTR_SERVICE_NAME]: "re-social-backend" }),
    spanProcessors: [new BatchSpanProcessor(exporter)],
  });
  trace.setGlobalTracerProvider(provider);
  propagation.setGlobalPropagator(new W3CTraceContextPropagator());
}

OTel Middleware

src/middleware/otel-middleware.ts must be registered before httpLogger. It extracts traceparent from incoming headers, starts a root HTTP span, stores traceId and spanId on the Hono context, and runs the rest of the request inside otelContext.with(...) so DB child spans auto-parent:

app.use("*", otelMiddleware); // first
app.use("*", httpLogger);     // second — reads traceId/spanId set above

On error, the span records the exception and sets SpanStatusCode.ERROR. On success, SpanStatusCode.OK.

Error-Only Span Sampling

The key cost optimization: spans are always created in memory (negligible overhead on the happy path), but only error spans actually reach ClickHouse:

export(spans, resultCallback) {
  for (const span of spans) {
    const isError = span.status?.code === SpanStatusCode.ERROR;
    const hasException = span.events.some(e => e.name === "exception");
    if (!isError && !hasException) continue; // skip happy-path spans
    this.buffer.push(JSON.stringify(spanToRow(span)));
  }
  // ...
}

Result: ClickHouse only stores traces that matter. The trace waterfall in ClickStack shows error spans only — which is exactly what you need when debugging a failed request.

ClickHouse Schema

Logs Table

CREATE TABLE IF NOT EXISTS app_logs
(
    timestamp         DateTime64(3, 'UTC')         CODEC(Delta, ZSTD(1)),
    level             LowCardinality(String)        CODEC(ZSTD(1)),
    message           String                        CODEC(ZSTD(1)),
    service           LowCardinality(String)        CODEC(ZSTD(1)),
    request_id        String          DEFAULT '',
    user_id           String          DEFAULT '',
    method            LowCardinality(String) DEFAULT '',
    path              String          DEFAULT '',
    status            UInt16          DEFAULT 0,
    latency           Float32         DEFAULT 0,
    db_query_count    UInt16          DEFAULT 0,
    db_total_duration Float32         DEFAULT 0,
    err_type          String          DEFAULT '',
    err_message       String          DEFAULT '',
    err_stack         String          DEFAULT '',
    log_attributes    Map(LowCardinality(String), String) DEFAULT map()
)
ENGINE = MergeTree()
PARTITION BY toYYYYMM(timestamp)
ORDER BY (timestamp, level, service)
TTL toDateTime(timestamp) + INTERVAL 30 DAY;

• LowCardinality(String) for level, method, service — dictionary-encoded integers internally, ~10x compression on repeated values
• log_attributes as Map(LowCardinality(String), String) — flexible key/value bag for anything that doesn't fit fixed columns, queryable with log_attributes['key']
• CODEC(Delta, ZSTD(1)) on timestamp — Delta encoding + ZSTD is optimal for monotonically increasing time columns
• 30-day TTL — logs auto-expire, no manual cleanup

Traces Table

CREATE TABLE IF NOT EXISTS otel_traces
(
    Timestamp          DateTime64(3, 'UTC') CODEC(Delta, ZSTD(1)),
    TraceId            String DEFAULT '',
    SpanId             String DEFAULT '',
    ParentSpanId       String DEFAULT '',
    SpanName           LowCardinality(String) DEFAULT '',
    SpanKind           LowCardinality(String) DEFAULT '',
    ServiceName        LowCardinality(String) DEFAULT '',
    Duration           UInt64 DEFAULT 0,
    StatusCode         LowCardinality(String) DEFAULT '',
    SpanAttributes     Map(LowCardinality(String), String),
    ResourceAttributes Map(LowCardinality(String), String),
    Events             String DEFAULT '',
    -- bloom filter indexes for fast TraceId lookups
    INDEX idx_trace_id TraceId TYPE bloom_filter(0.001) GRANULARITY 1,
    INDEX idx_span_attr_key mapKeys(SpanAttributes) TYPE bloom_filter(0.01) GRANULARITY 1
)
ENGINE = MergeTree()
PARTITION BY toYYYYMM(Timestamp)
ORDER BY (ServiceName, SpanName, toUnixTimestamp(Timestamp), TraceId)
TTL toDateTime(Timestamp) + INTERVAL 30 DAY;

Bloom filter index on TraceId makes point lookups (WHERE TraceId = '...') fast without a full scan. Schema mirrors the standard OTel ClickHouse exporter format so ClickStack recognizes it as a trace data source out of the box.

Log-Trace Correlation View

The bridge between logs and traces is a SQL view. ClickStack's Related Logs panel queries this view by TraceId. When you click a span in the trace waterfall, the panel shows every Pino log line that fired during that exact request:

CREATE OR REPLACE VIEW otel_app_logs AS
SELECT
    timestamp AS Timestamp,
    level AS SeverityText,
    message AS Body,
    service AS ServiceName,
    -- Use OTel trace_id when present, fall back to request_id for legacy logs
    if(log_attributes['trace_id'] != '', log_attributes['trace_id'], request_id) AS TraceId,
    if(log_attributes['span_id'] != '', log_attributes['span_id'], '') AS SpanId,
    log_attributes AS LogAttributes,
    ...
FROM app_logs;

The ClickHouse Transport

src/lib/clickhouse-transport.ts is a pino-abstract-transport worker. Pino runs it in a separate worker thread so inserts never block the event loop. It batch-inserts via ClickHouse's HTTP interface using INSERT INTO app_logs FORMAT JSONEachRow:

const insertUrl = `${url}/?database=${database}&query=${encodeURIComponent(
  `INSERT INTO ${table} FORMAT JSONEachRow`
)}`;

JSONEachRow format means each row is one JSON line separated by newlines — simple to construct, fast to parse on the ClickHouse side. Batching: buffer fills up to batchSize (default 100 rows), or flushes after flushIntervalMs (default 1s). On process exit/drain, remaining buffer is flushed. mapToRow() maps Pino's log object to the app_logs schema — known fields get dedicated columns, everything else falls into log_attributes as stringified key/value pairs. Nested objects are flattened (responseBody.userId → responseBody_userId) to avoid ClickHouse's Map equality WHERE clause limitations in ClickStack.

The Span Exporter

src/lib/clickhouse-span-exporter.ts implements the OTel SpanExporter interface. Same pattern — batched HTTP inserts, error-only filtering, flush-on-shutdown. The trickiest conversion is HrTime (an [seconds, nanoseconds] tuple) to ClickHouse's DateTime64(3):

function hrTimeToClickHouse(hrTime: HrTime): string {
  const [seconds, nanoseconds] = hrTime;
  const ms = seconds * 1000 + Math.floor(nanoseconds / 1e6);
  return new Date(ms).toISOString().replace("T", " ").slice(0, 23);
}

Duration is stored as nanoseconds (UInt64) matching the OTel spec, so ClickStack can display it as 142ms without unit confusion.

Middleware Order Matters

The registration order in src/api.ts is load-bearing:

app.use("*", otelMiddleware);       // 1. Starts span, sets traceId on ctx
app.use("*", httpLogger);            // 2. Reads traceId, creates Pino child
app.use("*", requestTimeout);        // 3. Needs requestId (set by httpLogger)
app.use("*", requestDbMiddleware);   // 4. Injects trackedDb into ctx
app.use("*", authMiddleware);        // 5. Reads db from ctx, sets user
// route handlers                    // 6. Use ctx.get("logger"), ctx.get("db")
app.onError(globalErrorHandler);     // 7. Sets requestError on ctx
                                     //    httpLogger finally block reads it

• otelMiddleware before httpLogger: the Pino child needs traceId at creation time. Flip these and every log line in the request loses its trace correlation.
• httpLogger before requestDbMiddleware: the tracked db middleware needs logger on context to log slow queries.
• authMiddleware after requestDbMiddleware: auth queries go through the tracked db, so they show up in dbQueryCount.

What We Can Answer Now

Before: "The feed is broken." After:

requestId: 9d4e12ab
traceId:   4a8f3c2e1b9d...
userId:    a3f8c2b1
method:    POST
path:      /api/v1/feed/posts
status:    500
latency:   3420ms
dbQueryCount: 12
dbTotalDuration: 3180ms
dbSlowQueries: 3
err: Error: Connection timeout
  at Pool.connect (pg-pool/index.js:87)

ClickStack trace waterfall shows exactly which of the 12 DB spans timed out. Related logs panel shows every logger.debug() call from that handler during that specific request. One request → one canonical log line → one trace → fully correlated, queryable, 30-day retention, zero-cost happy path.

Environment Variables

# Required for ClickHouse logging + tracing
CLICKHOUSE_URL=http://your-clickhouse:8123
CLICKHOUSE_USER=default
CLICKHOUSE_PASSWORD=secret
CLICKHOUSE_DATABASE=default
CLICKHOUSE_LOGS_TABLE=app_logs   # optional, defaults to app_logs

# Controls log verbosity
APP_ENV=local|development|production
LOG_LEVEL=debug|info|warn|error  # overrides APP_ENV default

When CLICKHOUSE_URL is not set, both the Pino transport and OTel exporter are disabled. The app works fine — logs go to stdout, no tracing. Good for CI and test environments.

Summary