Answering “how many order syncs failed yesterday, and for how many distinct customers” took twenty minutes, three regular expressions and a spreadsheet. The information was all there. It was in prose.
The symptom
$ grep 'sync failed' /var/log/app/2021-03-15.log | head -3
[2021-03-15 09:41:02] production.ERROR: Order 8814 sync failed
for user 4471: Connection timed out after 30000ms
[2021-03-15 09:41:19] production.ERROR: Order 8815 sync failed
for user 4471: cURL error 28
$ grep -c 'sync failed' /var/log/app/2021-03-15.log
412
# and the actual question:
# distinct users? a regex and a sort -u
# by error type? the messages are not consistent
# correlated with a deploy? the timestamps are, barelyEvery one of those follow-up questions needs a new expression, and each expression encodes an assumption about a message format that nobody has ever declared. The first time somebody changes the wording, every query silently returns nothing.
Why it happens
A log line starts as something a developer reads while writing the feature, and the interpolated message is the natural way to write it. It becomes an operational record later, without anybody deciding, and by then there are four thousand of them.
The fix
The message becomes an event name
// a unique string per occurrence. cannot be counted.
Log::error("Order {$order->id} sync failed for user {$user->id}: {$e->getMessage()}");
// a stable name, and everything variable in context
Log::error('order.sync.failed', [
'order_id' => $order->id,
'user_id' => $user->id,
'attempt' => $attempt,
'error_kind' => $this->classify($e),
'duration_ms'=> $elapsed,
]);A dotted event name in the message field is what makes grouping possible, and the naming scheme matters more than it looks — subject.action.outcome is a convention that survives contact with a team, where free-form names diverge within a month.
error_kind rather than the raw exception message is the second half. The message from a network library is unbounded and contains addresses and timings, so counting by it produces four hundred distinct values; a small classified set produces four.
private function classify(Throwable ): string
{
return match (true) {
instanceof ConnectionException => 'connection',
instanceof RequestException
&& ->response?->serverError() => 'upstream_5xx',
instanceof RequestException => 'upstream_4xx',
instanceof ValidationException => 'invalid_payload',
default => 'unknown',
};
}The fields that belong on every line
// a processor, so nothing has to remember
final class ContextProcessor
{
public function __invoke(array $record): array
{
$record['extra'] += [
'service' => config('app.name'),
'environment' => config('app.env'),
'version' => config('app.version'),
'host' => gethostname(),
'trace_id' => Trace::current()?->id(),
'user_id' => auth()->id(),
];
return $record;
}
}The version field is the one that repays itself fastest: “did this start with the deploy at 14:20” is a question asked during most incidents and is otherwise answered by correlating timestamps against a deployment log somewhere else.
Putting these in a processor rather than at each call site is what makes them reliable. A convention that every log call includes the trace id is a convention that will be broken by the third person to write one under pressure.
The formatter, and the local-development objection
// config/logging.php
'channels' => [
'stdout' => [
'driver' => 'monolog',
'handler' => StreamHandler::class,
'with' => ['stream' => 'php://stdout'],
'formatter' => env('LOG_PRETTY', false)
? LineFormatter::class
: JsonFormatter::class,
'processors' => [ContextProcessor::class, RedactingProcessor::class],
],
],The objection that JSON logs are unreadable on a terminal is legitimate and is entirely solved by a formatter switch plus jq. Dismissing it is how a structured logging initiative gets quietly reverted by whoever is debugging at the time.
# the local view
$ docker compose logs -f php | jq -r
'select(.level_name=="ERROR") |
"(.datetime) (.message) (.context.error_kind // "")"'
# and the question from the top of this post, in one line
$ jq -r 'select(.message=="order.sync.failed") | .context.user_id'
2021-03-15.log | sort -u | wc -l
7Redaction that is structural
final class RedactingProcessor
{
private const REDACT = ['password', 'password_confirmation', 'token',
'authorization', 'card_number', 'cvv', 'secret'];
public function __invoke(array $record): array
{
array_walk_recursive($record['context'], static function (&$v, $k): void {
if (in_array(strtolower((string) $k), self::REDACT, true)) {
$v = '[redacted]';
}
});
return $record;
}
}Redacting by key only works because the logs are structured — a formatted message has no keys, so the only option is a pattern over the text, which fails on the first format nobody anticipated. This is the security argument for structured logging and it is stronger than the operational one.
The list is a denylist and is therefore incomplete by construction. An allowlist of loggable keys is stricter, is considerably more work, and is the right choice for anything touching payment data — which is a decision to make deliberately rather than to discover during an audit.
Verifying it worked
# every line parses
$ jq -e . < /var/log/app/2021-03-22.log > /dev/null && echo ok
ok
# nothing sensitive escaped
$ jq -r '.. | strings' 2021-03-22.log | grep -cE '^[0-9]{13,19}$'
0
# and the question, answered in one command
$ jq -r 'select(.message=="order.sync.failed") | .context.error_kind'
2021-03-22.log | sort | uniq -c | sort -rn
388 connection
21 upstream_5xx
3 invalid_payloadAsserting that every line is valid JSON belongs in a test, because a single line written with a raw error_log call breaks a whole day of ingestion in most log pipelines. The card-number grep is a crude check and it has caught a real leak more than once.
The distribution at the end is the payoff: 388 connection errors and 21 upstream failures is a different incident from 388 upstream failures, and the old logs could not distinguish them without reading.
What this costs
Every log call site changes, which on a codebase of this size was about six hundred of them, and most of the diff is mechanical and boring. A regular expression finds the interpolated ones and cannot decide what the event name should be, so a person reads every one. Doing it a module at a time over a quarter is the version that gets finished.
The other cost is that the log is bigger — JSON with a dozen context fields is several times the bytes of a sentence — and the fields are what make it useful, so trimming them is trimming the value. Shorter retention on the verbose channels and a longer one on the business events is the trade that worked, and it requires deciding which is which.