Structured Logging mit JSON, Fluentd und MongoDB

19. Februar 2012 – In der Vergangenheit war die Logdatei hauptsächlich ein Protokoll jener Systemereignisse, die später zur Diagnose des Programmverhaltens und der Fehlerbehebung dienen sollten. Doch das ist nicht mehr gut genug.

A/B Testing, Realtime Analytics, Data Science uvm. haben die Rolle der Logs erweitert. Konsument sind nicht mehr nur Menschen, sondern zunehmend andere Maschinen.

Rivvabot loggt gerne und viel. Ich war nun auf der Suche nach einer Lösung, die mich echte, beliebig schachtelbare Datenstrukturen loggen lässt und die gleichzeitig meinen Code vom Logging Clutter säubert.

Ein Beispiel aus Rivvas neuem Feedfetcher:

def fetch_url
  intent 'About to fetch feed'
  response = Robot.fetch(url)

  if response.success?
    success 'Fetched feed'
    return response
  else
    error 'Error fetching feed', :status => response.response_code
    return nil
  end
end

intent, success und error sind hier Log-Anweisungen, die ich als Kernel Methods in alle Ruby-Objekte reingemixt habe und die im Initializer an konkrete Log-Levels (debug, info, warn, error, fatal) gebunden werden. Mir gefällt daran, wie das Logging dem Code eine fast narrative Struktur gibt.

Noch ein Stückchen aus dem Robot:

def get(options = {})
  intent 'About to fetch document'
  @response = http_get(@uri, options)

  success 'Fetched document',
    :status     => response_code,
    :uri        => effective_url,
    :origin     => origin,
    :size       => downloaded_bytes,
    :type       => content_type,
    :error      => acceptable?(content_type),
    :fetch_time => total_time
  return self
end

Die hier protokollierten sieben Attribute werden nicht mehr im dummen Format String in ein Log File geschrieben, sondern als semistrukturierter JSON String, einfach zu parsender Key/Value-Paare, zum zuständigen Event Collection Server gestreamt. Als Log Aggregator setze ich Fluentd ein.

Fluentd nun sammelt die Logs aller Nodes in einer Mongo-Instanz. Da MongoDB dokumentenorientiert ist, wird jede Log Message mit all ihren Feldern indiziert und damit beliebig queryable.

db.logs.findOne({ origin: 'https://blog.rivva.de/rss' })
{
  "_id" : ObjectId("4f40329d1645465463000003"),
  "type" : "text/xml; charset=UTF-8",
  "status" : 200,
  "message" : "Fetched document",
  "system" : "feedfetcher",
  "node" : "search.rivva.de",
  "fetch_time" : 0.765,
  "severity" : "info",
  "time" : ISODate("2012-02-18T23:22:04Z"),
  "size" : 14799,
  "uri" : "http://feeds.feedburner.com/rivvablog",
  "pid" : 87369,
  "error" : null,
  "origin" : "https://blog.rivva.de/rss"
}

Ersichtlich ist hier auch, wie der Hash automatisch noch um weitere Kontextinformationen aus ActiveRecord und Systemumgebung erweitert wird.

Gegen diese Collection kann ich jetzt beliebige Queries formulieren. Zum Beispiel:

„Wann haben wir diesen Feed zuletzt gesehen?“

db.logs.find({ origin: 'https://blog.rivva.de/rss' }).sort({ time: -1 }).limit(1)

„Welche Quellen sind heute verstorben?“

db.logs.find('this.status == 404 && this.time > ISODate("2012-02-19T")')

„Wie viele Fehler dieser Art gab es?“

db.logs.count(
  { $or: [
    { 'exception.message': /HostResolutionError/ },
    { 'exception.stacktrace': /robot\.rb/ }
  ] }
)

Vorerst pusht Rivva nur um die 2,4 Millionen Events täglich, insbesondere weil ich immer noch mit der Größe von Mongos Capped Collection experimentiere (momentan: 1 GB, Tradeoff: Speicherbelegung vs. Langzeitarchivierung).

Write Logs for Machines, use JSON – Paul Querna
Fluentd: the missing log collector – Treasure Data
Logging Application Behavior to MongoDB – Robert Stewart (SlideShare)