A system log story

Avishai Ish-Shalom

CTO & Co-Founder @Fewbytes

Logs are a gold mine, they provide the insights into the internal working of the application and complete data-set of its behaviour

As such they should be treated as a feature for both business and operations

Logs are born in sin:

a log story

While spending numerous hours developing his application, the developer feels an urge to see its intimate parts

The developer takes the application out for drinks, one glass leads to another and several lines of code later a log is born

At first, life could't be easier for the little log, running cheerfully on the developer's machine encountering almost no load

As days go by, the log records more and more data, so the developer decides to organize it using levels, categories and tags

The application is now fully grown and wants to move out

The app and it's log find a nice apartment with some roommates in a busy town called productionville

Like a fish out of water, having come to this world unplanned and having developed no social skills growing up, the log is incapable of decent interaction

Poor log, trying to communicate with the world :(

it's too big and disturbed for human interaction, but machines don't like it either

Broken dates

9/10/2012 12:28:10 - streaming full screen_36355_multistream_2 : bad stream found, as not audio nor video can be detected, closing & retrying

Unstructured data - unreasonably hard to parse

91.201.64.24 - - [12/Jan/2013:08:02:16 +0200] "GET /wiki/index.php?title=%D7%9E%D7%99%D7%95%D7%97%D7%93:%D7%A9%D7%99%D7%A0%D7%95%D7%99%D7%99%D7%9D_%D7%90%D7%97%D7%A8%D7%95%D7%A0%D7%99%D7%9D&days=30&hideminor=1&hidebots=&hideanons=1&hideliu=1&hidemyself=1 HTTP/1.1" 301 184 "-" "Mozilla/5.0 (X11; U; Linux i686; pl; rv:1.8.0.7) Gecko/20060914 Firefox/1.5.0.7 (Swiftfox)"
Some people, when confronted with a problem, think 'I know, I'll use regular expressions.' ...
Jamie Zawinski

That log line is parsed by this:

(?(?(?:(?\\b(?:[0-9A-Za-z][0-9A-Za-z-]{0,62})(?:\\.(?:[0-9A-Za-z][0-9A-Za-z-]{0,62}))*(\\.?|\\b))|(?(?(?[a-zA-Z0-9_-]+)) (?(?[a-zA-Z0-9_-]+)) \\[(?(?(?:(?:0[1-9])|(?:[12][0-9])|(?:3[01])|[1-9]))/(?\\b(?:Jan(?:uary)?|Feb(?:ruary)?|Mar(?:ch)?|Apr(?:il)?|May|Jun(?:e)?|Jul(?:y)?|Aug(?:ust)?|Sep(?:tember)?|Oct(?:ober)?|Nov(?:ember)?|Dec(?:ember)?)\\b)/(?(?>\\d\\d){1,2}):(?(?!<[0-9])(?(?:2[0123]|[01][0-9])):(?(?:[0-5][0-9]))(?::(?(?:(?:[0-5][0-9]|60)(?:[.,][0-9]+)?)))(?![0-9])) (?(?:[+-]?(?:[0-9]+))))\\] "(?:(?\\b\\w+\\b) (?\\S+)(?: HTTP/(?(?:(?(?[+-]?(?:(?:[0-9]+(?:\\.[0-9]+)?)|(?:\\.[0-9]+)))))))?|-)" (?(?:(?(?[+-]?(?:(?:[0-9]+(?:\\.[0-9]+)?)|(?:\\.[0-9]+)))))) (?:(?(?:(?(?[+-]?(?:(?:[0-9]+(?:\\.[0-9]+)?)|(?:\\.[0-9]+))))))|-) (?(?(?>(?"(?>\\\\.|[^\\\\"]+)+"|""|(?>'(?>\\\\.|[^\\\\']+)+')|''|(?>`(?>\\\\.|[^\\\\`]+)+`)|``)))) (?(?(?>(?"(?>\\\\.|[^\\\\"]+)+"|""|(?>'(?>\\\\.|[^\\\\']+)+')|''|(?>`(?>\\\\.|[^\\\\`]+)+`)|``)))))

I SH*T you not

... Now they have two problems.
Jamie Zawinski

No event boundaries

2013-01-12 16:33:55  [ERROR] [org.harpstore.PreProcessorImpl(?)] - Problems reading file
    org.codehaus.jackson.JsonParseException: Unexpected character
        ('F' (code 70)): was expecting comma to separate OBJECT entries
    at [Source: java.io.StringReader@1d796d7b; line: 1, column: 124]
    at org.codehaus.jackson.JsonParser._constructError(JsonParser.java:1291)
    at org.codehaus.jackson.impl.JsonParserMinimalBase._reportError(JsonParserMinimalBase.java:385)

Log priority is misleading

In effect, there are only two log levels

  • Too much bullshit
  • I'm f*cking blind

You don't generally know what's relevant in advance

No battle plan ever survives first contact with the enemy
Helmuth von Moltke

And there are other issues

  • Logs disappear
  • Service outages
  • Performance issues
  • Unnecessary operational costs
  • Hard to find stuff

Why does this happen?

People don't plan logging, it's a side-effect of the development process

Logging is (almost) never factored in as a feature

We can do better!

{
    "@timestamp": "2013-01-20T14:42:32.000Z", 
    "@source_path": "/var/log/apache/access_log.2013-01-20", 
    "@source": "file:///var/log/apache/access_log.2013-01-20", 
    "@source_host": "ip-10-194-114-79.ec2.internal", 
    "@message": "10.218.7.252 - - [20/Jan/2013:14:42:32 +0000] \"GET / HTTP/1.1\" 200 763 \"BlackBerry9810/7.0.0.261 Profile/MIDP-2.0 Configuration/CLDC-1.1 VendorID/102\"", 
    "@type": "apache-access-log",
    "@tags": [], 
    "@fields": {
        "response_code": [
            "200"
        ], 
        "request": [
            "/"
        ], 
        "auth": [
            "-"
        ], 
        "verb": [
            "GET"
        ], 
        "ident": [
            "-"
        ], 
        "user_agent": [
            "BlackBerry9810/7.0.0.261 Profile/MIDP-2.0 Configuration/CLDC-1.1 VendorID/102"
        ], 
        "clientip": [
            "10.218.7.252"
        ], 
        "bytes": [
            "763"
        ], 
        "X_Forwarded_For": [
            "166.205.68.25"
        ], 
        "httpversion": [
            "1.1"
        ]
    } 
}
                        

Use a proper logger

  • Logback
  • log4*

Use a well defined and structured format

  • Serialized logs (JSON, MsgPack)
  • CSV, key/value
  • Clear event separation
  • Classify, tag
  • As a rule, don't invent your own

Get a pipeline

  • Logstash
  • Fluentd
  • Graylog2
  • Kafka
  • Flume
  • Plain old rsyslog

Log remotely, especially when using a cloud

Implement flexible logging

  • Retroactive logging
  • Dynamic log level

Instrument your system

Hook as many parts of the system as you can and send events to the pipeline

Do something useful with the data

  • Use log analyzer/search engine
  • Create graphs
  • Leverage CEP (Complex Event Processing)
  • Generate statistics

Logstash, a glimpse

An open source, lightweight tool for managing events and logs, built on the Unix pipe metaphor

Key features

  • Simple to get started
  • 28 input plugins | 24 filter plugins | 48 output plugins (and counting)
  • Writing new plugins is easy
  • Active community and ecosystem
  • Scalable

Log management with Logstash

Kibana

An open source, browser based interface to Logstash and ElasticSearch

Grok

A logstash filter, enables parsing of crappy unstructured log data into something structured and queryable

%{DATESTAMP} %{LOGLEVEL}\s+(%{URI}|%{GREEDYDATA})

Riemann

A network event stream processing system

Thank you

And happy logging