Centralised logging that answers a question

The question was “when did this start”. It took forty minutes to answer, and the answer was wrong by two hours because one of the four servers had a clock that had drifted and nobody checked. That is not a tooling gap so much as a structural one: logs are written per machine and per process, and an incident is neither.

The symptom

Answering anything meant SSH, and the shape of the command was always the same.

$ for h in web01 web02 web03 worker01; do
>   ssh $h "grep -h 'order 91204' /var/log/nginx/access.log 
>     /var/log/php-fpm/error.log /var/log/app/*.log 2>/dev/null"
> done | sort

# and then, an hour later, the realisation that the interesting
# request was on web02 at 14:22 and web02 believes it is 16:22.

Every incident produced the same forty minutes, and the output could not be shared with anyone who did not have SSH. The postmortem was reconstructed from three of the eleven files because the other eight were never opened — not because they were irrelevant, but because nobody knew they existed.

Why it happens

Log files are a per-process artefact and they were designed when a process was the unit of deployment. A request that touches nginx, PHP-FPM, the application, a queue worker and a database sitting on four machines produces five files in four places, in four formats, and correlating them is a manual join on timestamps that are only approximately comparable.

The instinct is to reach for a tool, and the mistake is to reach for the parsing before the shipping. A pipeline that tries to parse eleven formats on day one is a pipeline that is still being configured on day thirty, with nothing in it.

The fix

Ship first, parse second

The first version shipped every line, unparsed, with three fields attached: which host, which file, and when it was read. That is enough to replace the SSH loop entirely, and it can be running the same afternoon.

# filebeat.yml — the whole of the first version
filebeat.prospectors:
  - type: log
    paths:
      - /var/log/nginx/*.log
      - /var/log/php-fpm/*.log
      - /var/log/app/*.log
    fields:
      env: production
    fields_under_root: true

    multiline.pattern: '^[?[0-9]{4}-[0-9]{2}-[0-9]{2}'
    multiline.negate: true
    multiline.match: after

output.logstash:
  hosts: ["logstash.internal:5044"]

The multiline block is not optional and is the thing most often left until later. A PHP stack trace is thirty lines, and shipping it as thirty documents makes it unsearchable — the pattern says a new event starts with a date and everything else belongs to the previous one.

# the same question, on day one of the pipeline
$ curl -s 'http://es.internal:9200/logs-*/_search?q=91204&sort=@timestamp' 
    | jq -r '.hits.hits[]._source | "(.host) (.source) (.message)"'

web02 /var/log/nginx/access.log   POST /orders HTTP/1.1 500 0.412
web02 /var/log/app/laravel.log    [2017-10-11 14:22:07] production.ERROR
worker01 /var/log/app/queue.log   [2017-10-11 14:22:09] Job failed

Unparsed and unstructured, and it already answers the question in seconds rather than forty minutes, with the clocks normalised because the shipper stamps arrival time. Everything after this is improvement rather than enablement, which is the right order to build in.

Structured logging, and why the format is the whole decision

Parsing a human-readable log line with a regular expression works until somebody changes the wording. Emitting JSON in the first place moves the structure to where it is known, and in 2017 every PHP logging library can do it with a handler swap.

// config/logging — Monolog with a JSON formatter
$handler = new StreamHandler(storage_path('logs/app.json'), Logger::INFO);
$handler->setFormatter(new JsonFormatter());

// and the call site changes shape: the message becomes a constant
// and everything variable becomes context.

// before — unparseable without a regex per message
Log::error("Payment failed for order 91204: card declined (code 51)");

// after
Log::error('payment.failed', [
    'order_id'    => $order->id,
    'reason'      => 'card_declined',
    'gateway_code'=> 51,
    'amount_cents'=> $order->totalCents(),
]);

The message becoming a constant is the change that matters and the one developers resist, because the line reads worse. It reads worse to a human tailing a file and enormously better to anything that aggregates: “how many payments failed, grouped by reason, this week” is a query rather than a research project.

{
  "template": "logs-*",
  "mappings": {
    "_default_": {
      "dynamic_templates": [
        { "strings": {
            "match_mapping_type": "string",
            "mapping": { "type": "keyword", "ignore_above": 1024 }
        }}
      ],
      "properties": {
        "@timestamp":     { "type": "date" },
        "correlation_id": { "type": "keyword" },
        "order_id":       { "type": "long" },
        "message":        { "type": "text" }
      }
    }
  }
}

Defaulting strings to keyword rather than analysed text is the other decision worth making up front. Analysed text is for prose; a hostname, a status and a reason code are values to filter and aggregate on, and analysing them doubles the index size while making exact matching unreliable.

A correlation id through every service

This is the thing that turns a searchable pile of lines into an answer. One identifier, generated at the edge, attached to every log line the request produces anywhere.

final class AttachCorrelationId
{
    public function handle($request, Closure $next)
    {
        $id = $request->header('X-Correlation-Id') ?: (string) Str::uuid();

        // every Log:: call for the rest of this request carries it
        Log::withContext(['correlation_id' => $id]);

        $response = $next($request);
        $response->headers->set('X-Correlation-Id', $id);

        return $response;
    }
}

// outbound HTTP passes it on
$this->http->post($url, ['headers' => ['X-Correlation-Id' => $id]]);

// and a queued job carries it, or the trail stops at the queue
class ProcessOrder implements ShouldQueue
{
    public $correlationId;

    public function handle()
    {
        Log::withContext(['correlation_id' => $this->correlationId]);
    }
}

Accepting an inbound header rather than always generating means a trail that starts at the load balancer or in a mobile client, which is worth having. Returning it in the response means a support ticket can quote it, and “the id from the error page” is a better bug report than any description.

The queue case is the one that gets missed, and it is where most of the value is. A request that enqueues work and returns is exactly the request whose failure is hardest to trace, because the interesting part happens on another machine, minutes later, in a different log file.

$ curl -s 'http://es.internal:9200/logs-*/_search' -d '{
    "query": { "term": { "correlation_id": "3f9a-...-c1" }},
    "sort": [{"@timestamp": "asc"}]
  }' | jq -r '.hits.hits[]._source | "(.@timestamp) (.service) (.message)"'

14:22:06.881 nginx     POST /orders
14:22:06.902 checkout  order.received
14:22:07.114 checkout  payment.authorised
14:22:07.119 checkout  job.dispatched ProcessOrder
14:22:09.402 worker    job.started ProcessOrder
14:22:09.881 worker    inventory.reserve.failed  reason=timeout
14:22:39.884 worker    job.failed

That is the whole incident, in order, across three machines, in one query. It is also the artefact to paste into a postmortem, which means the postmortem stops being a reconstruction and starts being an explanation.

Retention, and the disk this will fill

Daily indices and a scheduled deletion, decided before the cluster is full rather than during the incident where it fills. Elasticsearch 5 has no lifecycle management built in, so this is Curator on a cron.

# curator — delete indices older than 30 days
actions:
  1:
    action: delete_indices
    filters:
      - filtertype: pattern
        kind: prefix
        value: logs-
      - filtertype: age
        source: name
        direction: older
        timestring: '%Y.%m.%d'
        unit: days
        unit_count: 30

  2:
    action: forcemerge
    options:
      max_num_segments: 1
    filters:
      - filtertype: age
        unit: days
        unit_count: 2

Age on the index name rather than on creation date is deliberate — it survives a reindex, where creation date does not. The force merge on indices older than two days halves the disk they occupy and costs nothing, because nothing is still writing to them.

Thirty days at roughly nine gigabytes a day was the sizing, and it was wrong within a month because turning on debug logging during an investigation tripled the volume for a week. A disk alert on the data nodes is the thing that actually protects the cluster, because a full Elasticsearch node does not degrade gracefully — it marks indices read-only and stays that way after the disk is cleared, until a setting is reset by hand.

Verifying it worked

# the drill: pick a past incident, answer it again from scratch
# "when did the checkout errors start, and what preceded them"
#
# before: 40 minutes, four SSH sessions, answer off by two hours
# after:  90 seconds, one query, timestamps normalised at ingest

$ curl -s 'http://es.internal:9200/logs-*/_search' -d '{
    "query": { "bool": { "filter": [
      { "term":  { "service": "checkout" }},
      { "term":  { "level": "error" }},
      { "range": { "@timestamp": { "gte": "now-24h" }}}
    ]}},
    "aggs": { "per_minute": {
      "date_histogram": { "field": "@timestamp", "interval": "minute" }
    }},
    "size": 0
  }' | jq '.aggregations.per_minute.buckets[] | select(.doc_count > 0)'

{ "key_as_string": "2017-10-11T14:22:00Z", "doc_count": 3 }
{ "key_as_string": "2017-10-11T14:23:00Z", "doc_count": 47 }

Re-answering a past incident is the honest test, because the pipeline was built with that incident in mind and it is easy to build something that only works for the question you already know. Doing it again with an incident nobody had in mind is the second test, and it is the one that found that the queue workers were not shipping at all.

What this costs

A cluster to run, which is three machines that did not exist before and that need upgrading, monitoring and backing up like anything else. Elasticsearch is not a component that tolerates neglect: a yellow cluster is normal, a red one is data loss, and the difference between them is often a disk that filled while nobody was looking. Budgeting for that operational load honestly, rather than treating the pipeline as a one-week project, is the difference between a tool people use and one that quietly stops ingesting in March.

The other cost is a security one and it arrives immediately. Logs are now aggregated, searchable and readable by everyone with a Kibana account, and everything that has ever been logged carelessly is now findable — request bodies with passwords, full card numbers in a gateway error, tokens in a URL. A redaction filter in the shipping pipeline is a requirement rather than a refinement, and it has to be written before the first document, because deleting from an index is far harder than never indexing.

# logstash — drop the fields that must never be indexed
filter {
  mutate {
    remove_field => [ "[request][password]", "[request][card_number]",
                      "[request][cvv]", "[headers][authorization]" ]
  }

  # and a coarse net for anything that looks like a card number
  mutate {
    gsub => [ "message", "b[0-9]{13,19}b", "[REDACTED]" ]
  }
}

The regular expression will occasionally redact an order number, and that is the correct trade. A field list catches what is known; the pattern catches what somebody logs next year in a code path nobody reviewed.