Operations / Knowing what it is doing
Tracing one document from request to delivery
Following a single document across the queue, the render and the delivery, which is the only way to answer where the time went or where it stopped.
Why the default answer is wrong here
Document generation is rarely one call. There is a request, possibly a queue, a render, a storage write and a delivery, usually across different processes and sometimes different services. When somebody asks why a document took four minutes, or where one went, the answer is in the join between those steps, and without a correlation identifier propagated through all of them the join does not exist. Each service logs correctly and nobody can reconstruct the story.
The decisions
Reasons rather than a description of the code. Each has a default that is defensible in general and wrong for documents specifically.
- Generate a correlation identifier at the entry point and propagate it through every step, including into the queue message and out the other side.
- Carry the document's own identity alongside it, so a trace can be found by document as well as by request. Support questions arrive as document numbers, not trace identifiers.
- Record a span per stage with its own duration, because the useful finding is usually that the render was fast and the queue wait was not.
- Propagate it into the callback path too. A webhook arriving later is part of the same story and it usually arrives with no context at all unless you attach some.
- Keep the identifier out of the document itself unless you intend it to be there, since anything printed on a document is visible to its recipient.
- Make it findable from the support side. An operator with an invoice number should be able to reach the trace without knowing anything about the architecture.
In practice
A fragment, with the thing that goes wrong kept in a comment where it is the more instructive half.
// One identifier, generated at the edge, present in every step and in
// the queue message that crosses process boundaries.
const correlationId = req.headers["x-correlation-id"] ?? randomUUID();
await queue.send({
correlationId,
kind: "invoice",
invoiceId: invoice.id, // findable by document, not just by trace
});
// In the worker
const span = tracer.start("document.generate", { correlationId, invoiceId });
const queued = span.child("queue.wait", { start: message.enqueuedAt });
queued.end(); // usually the surprising number
const rendered = span.child("render");
const res = await pdf.post("/v1/pdf", { html, store: true });
rendered.end({ bytes: res.body?.length, documentId: res.document_id });
const delivered = span.child("deliver");
await mailer.send({ to, attachments: [{ content: res.body }] });
delivered.end();
span.end();
// And an index the support side can actually use: given an invoice
// number, find the trace.
await db.documentTraces.create({ invoiceId: invoice.id, correlationId });
/* Keep the identifier off the document unless you mean it to be there.
Anything printed on a document is visible to its recipient. */What people do instead
Correlating only within the web request. The identifier stops at the queue boundary, the worker generates its own, and the two halves of the story cannot be joined, which is exactly the boundary the interesting delays live at.
What the symptom looks like
A trace where the render span is a small fraction of the total says the problem is not the renderer, which is the most common misdiagnosis in these pipelines. The queue wait is usually the larger number and it is invisible without the span.
Frequently asked
Is this worth doing for a small volume of documents?
Some of it, and the cheap parts are the ones that matter. Allocating a document's identity before rendering it costs nothing and prevents duplicates forever. Logging the template version costs one field and answers most support questions. Queue design, backpressure and capacity planning are genuinely for scale and can wait until there is some.
Why is duplication treated as more serious than latency here?
Because a document usually carries an identity. A duplicated read is harmless and a duplicated invoice is a second numbered document for one event, which somebody has to reconcile by hand and which may already have been sent. That asymmetry is why the correctness half of this cluster is larger than it would be for most APIs.
How does this relate to the troubleshooting pages?
Those start from a symptom you are looking at right now and work back to a cause. These start from a decision made before the symptom exists. The two meet in the middle: a decision skipped here usually appears there some months later as a problem with no obvious explanation.
Related operational topics
The decisions that depend on each other, then the rest of the same group.
What to log about a render, and what must never be logged
The fields that make a render diagnosable weeks later, and the one thing that must not be in the log at any level.
Measuring document latency in percentiles rather than averages
Recording the distribution rather than the mean, because document render times are skewed by document size and the tail is what people experience.
Setting timeouts along the whole path, not just in the client
Making the timeouts at each hop consistent with each other, because a path whose timeouts disagree fails in the least useful way available.
Alerting on document generation, including failures that return 200
Choosing signals that catch the failures that matter, which for documents includes several that produce no error at all.
Answering what happened to one document three weeks later
Keeping enough operational history that a specific document's story can be reconstructed, which log retention alone usually cannot do.
Every operational topic
The full list, grouped by correctness, visibility and cost.
What this API actually does
The options and endpoints these decisions are built on, one page each.
Most of these decisions are cheaper to make before the first production run than after the first incident, and none of them need a large system to be worth making.