ggozad / debug-ingestion

Debug ingestion in Logfire

The ingester ships spans to Logfire under service_name = 'haiku-ingester' (or a
custom OTEL_SERVICE_NAME if set per process). This skill finds failing jobs,
traces a document through the pipeline, and pinpoints the docling-serve instance
that served a request. Read-only.

How to query

1. Confirm the current schema with mcp__logfire__query_schema_reference (spans
   and logs share the records table).

2. Run SQL with mcp__logfire__query_run (query + project: "haiku" +
   start_timestamp/end_timestamp, max 14 days). The remote MCP is
   org-scoped, so project is required; the ingester ships to project haiku.
   The same SQL works pasted into Logfire's Explore UI.

3. Read span attributes as JSON: attributes->>'key', cast when needed
   ((attributes->>'attempt')::int).

4. Hand back a clickable trace with
   mcp__logfire__project_logfire_link(trace_id, project="haiku").

5. For recent exceptions tied to a file,
   mcp__logfire__query_find_exceptions_in_file accepts
   client/documents.py, ingester/workers/pool.py, or
   ingester/pollers/base.py.

Adjust service_name if the operator set OTEL_SERVICE_NAME (e.g. per tenant).
Interactive haiku-rag ingests emit the same document.* spans under the CLI's
service name (or unknown_service for older runs), not haiku-ingester.

Vocabulary

Span tree (all scope haiku.rag), each level nests under the one above and
shares its trace_id:

• Poller: ingester.poller.sweep | ingester.poller.dry_run |
  ingester.poller.watch_event.

  • attributes->>'source_id'; watch adds change, uri.

  • sweep sets skipped, skip_reason (pending_work / circuit_open),
    upsert, delete, unchanged, consecutive_failures. A failed sweep
    records the exception on the span (exception_type / exception_message).

• Job: ingester.job — attributes->>'source_id', ->>'uri', ->>'op'
  (UPSERT/DELETE), (->>'attempt')::int. is_exception=true marks a job
  that raised.

• Document pipeline, six sibling phases under ingester.job:
  document.fetch (bytes, content_hash), document.convert,
  document.chunk (chunks_created), document.embed, document.items,
  document.store. Each measures one phase only, and none contains another.
  They do not sum to the job: _prepare_and_title (create) and
  get_all_picture_data (update) run outside any phase span.

  • document.embed — (->>'chunks')::int (total on the document),
    chunks_embedded (how many lacked a vector; 0 means the phase was
    free, and the span is still emitted), images, batch_size. Provider
    round trips are ceil((chunks_embedded - images) / batch_size) + images:
    text goes out in batch_size groups, images one at a time.

  • document.items — extract_items on a worker thread. pictures,
    items, uri. Absent on an update that carries no docling document
    (existing items are preserved).

  • document.store — the LanceDB write. op (create / update /
    create_batch), document_id, uri, chunks, items, documents on
    a batch, and (->>'lock_wait_ms')::float, the time spent waiting on the
    write lock. op is set after the write on the create path, because a
    concurrent ingest of the same URI is only resolved under the lock.
    lock_wait_ms also lands on ingester.job for a DELETE, which writes
    without a document.store span. The lock is in-process, so contention
    between two ingester processes on one database is not measured.

• docling-serve: docling_serve.request — attributes->>'name' (operation),
  ->>'url' (instance), (->>'attempt')::int. A retry emits a new span with a
  different url, so failover shows as sibling spans.

Failures in Logfire are span-level: sweep and job exceptions sit on the span
(is_exception, exception_type, exception_message, level >= 17). A job that
raised PermanentError was dead-lettered on that attempt; attempt >= 2 on an
ingester.job span is a retry. The worker circuit breaker opening emits a
dedicated event span_name = 'ingester.worker breaker opened' (attributes
source_id, threshold, cooldown_s), fired once per closed->open transition.
The ingester's per-job dead/reschedule narration stays on stderr and the queue
(GET /jobs?status=dead on the control-plane API), not Logfire.

Canned queries

Job outcomes by source:

SELECT attributes->>'source_id' AS source_id,
       attributes->>'op' AS op,
       is_exception,
       count(*) AS n
FROM records
WHERE service_name='haiku-ingester' AND span_name='ingester.job'
GROUP BY 1,2,3
ORDER BY n DESC;

Failed jobs with the exception and trace to drill in:

SELECT attributes->>'uri' AS uri,
       (attributes->>'attempt')::int AS attempt,
       exception_type, exception_message, trace_id
FROM records
WHERE service_name='haiku-ingester' AND span_name='ingester.job'
  AND is_exception=true
ORDER BY start_timestamp DESC
LIMIT 50;

Retried and dead-lettered jobs (a PermanentError was dead-lettered on that
attempt; TransientError at a high attempt was retried):

SELECT attributes->>'uri' AS uri,
       (attributes->>'attempt')::int AS attempt,
       attributes->>'op' AS op,
       exception_type, trace_id
FROM records
WHERE service_name='haiku-ingester' AND span_name='ingester.job'
  AND (is_exception=true OR (attributes->>'attempt')::int > 1)
ORDER BY start_timestamp DESC
LIMIT 50;

Trace one document end-to-end (take trace_id from a job above):

SELECT span_name, duration, is_exception,
       attributes->>'url' AS docling_url,
       attributes->>'op' AS op
FROM records
WHERE trace_id='<TRACE_ID>'
ORDER BY start_timestamp;

Worker circuit-breaker trips (a source paused after consecutive transient
failures):

SELECT start_timestamp,
       attributes->>'source_id' AS source_id,
       (attributes->>'cooldown_s')::float AS cooldown_s
FROM records
WHERE service_name='haiku-ingester'
  AND span_name='ingester.worker breaker opened'
ORDER BY start_timestamp DESC
LIMIT 50;

docling-serve instance health and failover:

SELECT attributes->>'url' AS instance,
       (attributes->>'attempt')::int AS attempt,
       is_exception,
       count(*) AS n
FROM records
WHERE service_name='haiku-ingester' AND span_name='docling_serve.request'
GROUP BY 1,2,3
ORDER BY n DESC;

Slowest pipeline stages:

SELECT span_name,
       attributes->>'uri' AS uri,
       duration, trace_id
FROM records
WHERE service_name='haiku-ingester'
  AND span_name IN ('document.convert','docling_serve.request','document.embed',
                    'document.chunk','document.items','document.store')
ORDER BY duration DESC
LIMIT 20;

Where a job's time goes. The phase names are listed explicitly: `LIKE
'document.%'would also matchdocument.convert_slice`, which nests inside
document.convert when processing.split_pages is on, counting conversion
twice.

SELECT span_name, count(*) AS n,
       avg(duration) AS avg_s,
       sum(duration) AS total_s
FROM records
WHERE service_name='haiku-ingester'
  AND span_name IN ('document.fetch','document.convert','document.chunk',
                    'document.embed','document.items','document.store')
GROUP BY 1
ORDER BY total_s DESC;

Is storing slow, or just queued behind another writer?

SELECT attributes->>'uri' AS uri,
       attributes->>'op' AS op,
       (attributes->>'lock_wait_ms')::float AS lock_wait_ms,
       duration AS store_s,
       trace_id
FROM records
WHERE service_name='haiku-ingester' AND span_name='document.store'
ORDER BY lock_wait_ms DESC
LIMIT 20;

Embedding: provider latency or batch count?

SELECT ceil(((attributes->>'chunks_embedded')::int
             - (attributes->>'images')::int)::float
            / (attributes->>'batch_size')::int)
       + (attributes->>'images')::int AS batches,
       (attributes->>'chunks_embedded')::int AS chunks,
       duration,
       attributes->>'uri' AS uri
FROM records
WHERE service_name='haiku-ingester' AND span_name='document.embed'
  AND (attributes->>'chunks_embedded')::int > 0
ORDER BY duration DESC
LIMIT 20;

Per-source sweep summary:

SELECT attributes->>'source_id' AS source_id,
       sum((attributes->>'upsert')::int) AS upserts,
       sum((attributes->>'delete')::int) AS deletes,
       sum((attributes->>'unchanged')::int) AS unchanged,
       max(attributes->>'skip_reason') AS last_skip_reason
FROM records
WHERE service_name='haiku-ingester' AND span_name='ingester.poller.sweep'
GROUP BY 1;

Tell concurrent ingesters apart (set distinct OTEL_SERVICE_NAME per process; a
single host still separates by process_pid / service_instance_id):

SELECT service_name, service_instance_id, process_pid, count(*) AS n
FROM records
WHERE span_name='ingester.job'
GROUP BY 1,2,3
ORDER BY n DESC;

Workflow

1. Job outcomes by source shows where failures cluster.
2. Failed jobs surfaces the exception and each failing trace_id.

3. Trace one document end-to-end to see which stage failed and, for a docling
   source, which docling_url served it (and whether it failed over).

4. Retried/dead-lettered jobs show what the queue kept struggling with; a
   ingester.worker breaker opened event flags a source the pool paused. The
   per-job dead/reschedule narration stays in the ingester console and the queue
   API, not Logfire.

5. project_logfire_link(trace_id) for a document lets the user expand the
   full tree.

When a query returns nothing

Span names or attributes may have changed. Probe:

SELECT DISTINCT span_name
FROM records WHERE service_name='haiku-ingester'
ORDER BY 1;