Operations / Knowing what it is doing
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.
Why the default answer is wrong here
Document logging goes wrong in both directions at once. Too little, and a support question three weeks later, why does this customer's invoice look wrong, is unanswerable: there is no record of which template version rendered it, which options were used, or how long it took. Too much, and the log now contains the document's contents, which means the payslip is in a log aggregator with a different retention policy and a different access list from the document itself.
The decisions
Reasons rather than a description of the code. Each has a default that is defensible in general and wrong for documents specifically.
- Log the identity, not the content. A document identifier, the template version, the option set, the byte size, the page count and the duration answer nearly every question that will be asked.
- Never log the markup or the rendered bytes. The markup contains the data, which for most documents is the sensitive part, and it will outlive the document's own retention.
- Log the template version explicitly rather than inferring it from a deploy timestamp, because the question people ask is which template produced this file.
- Log the outcome including the error code on failure, since the codes distinguish transient from permanent and that distinction is what a later reader needs.
- Include a correlation identifier that reaches the render call, so a log line here can be joined to a request there.
- Log the cache or reuse decision, so a stale document can be diagnosed in one step rather than by elimination.
In practice
A fragment, with the thing that goes wrong kept in a comment where it is the more instructive half.
// Identity and shape, never content.
log.info("render.completed", {
correlationId: ctx.correlationId,
documentKind: "invoice",
documentId: res.document_id, // ours, or the stored one
subjectId: invoice.id, // what it is about
templateVersion: TEMPLATE_VERSION, // the question people actually ask
options: { format: "A4", landscape: false },
locale: "en-GB",
bytes: res.body.length,
pages: res.pages ?? null,
cached: false,
durationMs: Date.now() - startedAt,
});
log.warn("render.failed", {
correlationId: ctx.correlationId,
subjectId: invoice.id,
templateVersion: TEMPLATE_VERSION,
errorCode: err.code, // transient or permanent, later
status: err.status,
attempt,
durationMs: Date.now() - startedAt,
});
/* Never, at any level, including debug:
the markup it contains the data
the rendered bytes it is the document
the data object same reason as the markup
A debug line added during an incident is the usual way a payslip
ends up in a log aggregator with a different retention policy and a
different access list from the document itself. */What people do instead
Logging the request body during an incident to see what was wrong, and leaving it in. It is added under pressure, it is useful once, and afterwards every document's contents flow into a system that was never assessed for holding them.
What the symptom looks like
The test of a document log is whether it can answer a question about one specific file from three weeks ago. If the answer requires re-rendering to find out, the log is missing the template version, the options, or both.
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.
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.
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.
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.
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.