Logging Query Lifecycle Events for Debugging

“Why did this refetch?” is not answerable from a stack trace. By the time a request is on the wire, the decision that produced it — a focus event, an invalidation, an interval, a remount — is already several layers back, and none of it appears in queryFn. A structured lifecycle log records the decisions instead of the requests, which turns a class of unreproducible bug into a five-line answer. This page builds one, under Cache Observability & Debugging. It uses the same subscription as Measuring Cache Hit Rate in Production, keeping the detail that the metric aggregates away, and it complements the local view in Inspecting Cache State With React Query DevTools.

Prerequisites

  • A QueryClient you can subscribe to before any query is created.
  • An error reporter that accepts arbitrary context on a report.
  • Agreement on what may be logged: hashes and timings yes, response data no.
Where the work happens, and where it must not Cache events arrive on the notify path, where the handler does nothing but write a small fixed-shape record into a preallocated ring buffer. Formatting, redaction and serialization happen later, only when an error report or a support export reads the buffer. Cheap on the notify path, expensive only when someone reads it cache event added · updated · removed observerAdded · observerRemoved ring buffer write one preallocated slot no strings, no JSON read on demand error report or support export redact, format, serialize here What must never go in the handler JSON.stringify · template strings · console.log · fetch or sendBeacon · anything touching state.data The handler runs synchronously inside the notify cycle — before React re-renders. Its cost is interaction latency.
The discipline is the whole technique: the handler allocates one small object and returns. Everything else is deferred.

Step 1 — Write Into a Ring Buffer

A bounded buffer of fixed-shape records gives you the last few hundred decisions with no unbounded growth and no allocation churn.

export interface LifecycleRecord {
  at: number;
  kind: 'fetch' | 'success' | 'error' | 'observe' | 'unobserve' | 'invalidate' | 'remove';
  hash: string;
  observers: number;
  durationMs: number | null;
}

export function createRingBuffer(capacity = 400) {
  const slots: Array<LifecycleRecord | undefined> = new Array(capacity);
  let next = 0;

  return {
    push(record: LifecycleRecord) {
      slots[next] = record;
      next = (next + 1) % capacity;
    },
    /** Oldest-first, allocated only when someone actually reads. */
    drain(): LifecycleRecord[] {
      const out: LifecycleRecord[] = [];
      for (let i = 0; i < capacity; i++) {
        const record = slots[(next + i) % capacity];
        if (record) out.push(record);
      }
      return out;
    },
  };
}

Cache Behavior Analysis: The subscription handler runs synchronously inside the cache’s notify cycle, before React has been told to re-render, so any work done there lands directly on interaction latency — a JSON.stringify of a large key in that position is measurable on a mid-range phone. Writing a fixed-shape object with only primitives keeps the handler at a single allocation and lets the engine keep the shape monomorphic. Four hundred records covers several minutes of a busy session at roughly 20 kB of retained memory, which is a good default; a polling-heavy application may want fewer.

Step 2 — Attribute Each Fetch to Its Trigger

The event itself does not say why. Combining the observer count, the previous state and the elapsed time since the last event identifies the trigger reliably enough to debug with.

import type { QueryClient } from '@tanstack/react-query';

export function traceLifecycle(client: QueryClient, buffer: ReturnType<typeof createRingBuffer>) {
  const fetchStartedAt = new Map<string, number>();
  const lastObserverAt = new Map<string, number>();

  return client.getQueryCache().subscribe((event) => {
    const at = performance.now();
    const hash = event.query.queryHash;
    const observers = event.query.getObserversCount();

    if (event.type === 'observerAdded') {
      lastObserverAt.set(hash, at);
      buffer.push({ at, kind: 'observe', hash, observers, durationMs: null });
      return;
    }
    if (event.type === 'observerRemoved') {
      buffer.push({ at, kind: 'unobserve', hash, observers, durationMs: null });
      return;
    }
    if (event.type === 'removed') {
      buffer.push({ at, kind: 'remove', hash, observers, durationMs: null });
      return;
    }
    if (event.type !== 'updated') return;

    if (event.action.type === 'fetch') {
      fetchStartedAt.set(hash, at);
      buffer.push({ at, kind: 'fetch', hash, observers, durationMs: null });
    } else if (event.action.type === 'success' || event.action.type === 'error') {
      const started = fetchStartedAt.get(hash);
      buffer.push({
        at,
        kind: event.action.type,
        hash,
        observers,
        durationMs: started == null ? null : Math.round(at - started),
      });
      fetchStartedAt.delete(hash);
    } else if (event.action.type === 'invalidate') {
      buffer.push({ at, kind: 'invalidate', hash, observers, durationMs: null });
    }
  });
}

Cache Behavior Analysis: A fetch action within a few milliseconds of an observe for the same hash is a mount-driven fetch; one with no preceding observe and a preceding invalidate is invalidation-driven; one with neither, on a query that already has observers, is a timer or a focus event. That inference is what makes the log answer the “why” question, and it is only possible because the observer transitions are recorded alongside the fetches. Deleting from fetchStartedAt on completion is what stops the map becoming an unbounded leak of its own — a subtle failure that instrumentation code is unusually prone to.

A logged sequence that explains an unexpected refetch Timeline of six lifecycle records for one query hash: an observe at zero, a fetch at one millisecond, success at 210, an invalidate at 4,020 triggered by a mutation, a fetch at 4,021 and success at 4,190. A logged sequence that explains an unexpected refetch 0ms observe component mounted, 1 observer 1ms fetch no cached entry 210ms success duration 209ms 4,020ms invalidate mutation marked the prefix stale 4,190ms success duration 169ms
The invalidate record at 4,020 is the answer. Without it, the second fetch looks like a spontaneous refetch with no cause.

Step 3 — Correlate Mutations With the Invalidations They Cause

The MutationCache has its own stream. Recording both, on one clock, is what lets you connect a user action to the refetch burst that followed it.

export function traceMutations(client: QueryClient, buffer: ReturnType<typeof createRingBuffer>) {
  return client.getMutationCache().subscribe((event) => {
    if (event.type !== 'updated' || !event.mutation) return;

    const at = performance.now();
    // A mutation has no queryHash; use its mutationKey as the identity so the
    // record shares a shape with the query records and the buffer stays uniform.
    const hash = JSON.stringify(event.mutation.options.mutationKey ?? ['anonymous']);

    if (event.mutation.state.status === 'pending') {
      buffer.push({ at, kind: 'fetch', hash: `mutation:${hash}`, observers: 0, durationMs: null });
    }
    if (event.mutation.state.status === 'success' || event.mutation.state.status === 'error') {
      buffer.push({
        at,
        kind: event.mutation.state.status,
        hash: `mutation:${hash}`,
        observers: 0,
        durationMs: event.mutation.state.submittedAt
          ? Math.round(Date.now() - event.mutation.state.submittedAt)
          : null,
      });
    }
  });
}

Cache Behavior Analysis: Because both subscriptions push into the same buffer with performance.now() timestamps, the drained records interleave in true chronological order — a mutation success followed within a millisecond by four invalidate records and four fetch records is a complete, self-explanatory trace of an over-broad invalidation prefix. The JSON.stringify on the mutation key is the one place this design breaks its own rule about serializing on the notify path; mutation events are orders of magnitude rarer than query events, so the cost is acceptable, but keep mutation keys short. submittedAt is a wall-clock timestamp rather than a performance timestamp, which is why it is compared against Date.now() and not at.

Step 4 — Attach the Buffer to Error Reports

The log is most valuable at the moment something fails. Attaching it to a report costs nothing until then.

import * as Sentry from '@sentry/browser';

export function installCacheContext(buffer: ReturnType<typeof createRingBuffer>) {
  Sentry.addEventProcessor((event) => {
    const records = buffer.drain();
    if (records.length === 0) return event;

    const base = records[0].at;
    event.contexts = {
      ...event.contexts,
      queryCache: {
        // Relative timings are far easier to read than absolute ones, and they
        // avoid shipping anything that could correlate to a wall clock.
        recent: records.slice(-40).map((record) => ({
          t: Math.round(record.at - base),
          kind: record.kind,
          hash: redactHash(record.hash),
          obs: record.observers,
          ms: record.durationMs,
        })),
      },
    };
    return event;
  });
}

/** Keep the namespace and the shape; drop anything that could be user data. */
function redactHash(hash: string): string {
  try {
    const key = JSON.parse(hash) as unknown[];
    return [key[0], key[1], key.length > 2 ? `+${key.length - 2}` : ''].filter(Boolean).join('/');
  } catch {
    return 'unparsed';
  }
}

Cache Behavior Analysis: Draining and formatting inside the error processor means the entire cost is paid on a code path that is already exceptional, so a session that never errors pays only the ring-buffer writes. Redacting to namespace and arity keeps the diagnostic value — you can still see that todos/detail fetched four times in 200 milliseconds — while removing entity ids and filter contents from the report. Capping at the last forty records keeps the report payload small; the interesting window before a failure is almost always short.

Cost of the subscription handler per event Bar chart of microseconds per event. Pushing a fixed-shape record costs 1.4. Building a template string costs 18. Calling console.log costs 91. JSON stringifying the query data costs 640. Cost of the subscription handler per event Median over 10,000 events, mid-range Android device push a fixed-shape record 1.4 µs build a template string 18 µs console.log the event 91 µs JSON.stringify state.data 640 µs
The handler runs before React re-renders, so these microseconds are interaction latency. Only the first row is safe to do per event.

Edge Cases & Gotchas

Subscribe before the first query. A subscription installed inside a component misses everything that happened during bootstrap — which is exactly where prefetch and hydration bugs live. Install it immediately after constructing the client.

Development doubles the records. React strict mode mounts and unmounts effects twice, producing paired observe/unobserve records that do not occur in production. Read the log from a production build when the timing matters.

Query hashes can be long. A key carrying a large filter object produces a hash that dominates the record. Truncate the hash at write time if your keys are large, accepting the small risk of collision in the log.

Common Pitfalls & Resolutions

Observable Issue Root Cause Diagnostic Resolution
Interaction latency worsens after adding logging The handler serializes or logs on the notify path Push a primitive-only record; format on drain
The log misses the interesting events The subscription was installed inside a component, after bootstrap Subscribe immediately after creating the client
Memory grows in proportion to session length A correlation Map is written but never deleted Delete on completion, as fetchStartedAt does
Error reports contain user data Query keys with ids were logged verbatim Redact to namespace and arity before attaching
Every event appears twice locally React strict mode double-invokes effects Verify against a production build

Frequently Asked Questions

Why not just console.log inside queryFn?

Because queryFn only runs on a miss, and almost everything worth debugging happens when it does not run. The fetch that was skipped because the entry was still fresh, the observer that joined a request already in flight, the invalidation that marked a whole prefix stale, the query that was removed by garbage collection — none of those reach queryFn, and they are the events that explain the behaviour people actually report. Subscribing to the cache sees all of them, in order, on one clock.

Is subscribing to the cache expensive?

The subscription itself is a function call per event, which is negligible. What is expensive is what you put inside it, and the trap is that the handler runs synchronously inside the notify cycle — before React is told to re-render — so its cost lands directly on interaction latency rather than on some background task. A console.log per event is roughly sixty times the cost of pushing a record, and stringifying response data is several hundred times. Push primitives, format later.

How do I keep sensitive data out of the log?

Never record state.data — there is no redaction strategy for arbitrary response bodies that survives contact with a new endpoint. Record the hash, the status, the observer count and the timing, all of which are structural. When you need to know which resource a record refers to, pass the hash through a redactor that keeps the namespace and the arity and drops the rest, so ["todos","detail","u-8842"] becomes todos/detail/+1. That is enough to debug a refetch storm and contains nothing that identifies a user.