GoAccess is a top for Nginx or Apache

goaccess-dashboard

GoAccess is an open source real-time web log analyser and interactive viewer that runs in a terminal on Linux systems. The name suggest that is written in the Go language, but it actually is not (it is written in C).

Monitoring

Effectively it is like the “top” command, but instead of showing processes it is giving you insight in the traffic on your webserver. The tool provides all kinds of top lists useful for spotting irregularities. Great features include the listing of IP addresses by percentage of hits and showing the status codes of the served responses. Typically you would use this tool if your webserver is reporting high load or high bandwidth usage and you want to find out what is going on. The outcomes of the analysis with this tool can then be used to adjust your firewall or caching rules.

Installing

On my Ubuntu 15.04 I can install version 0.8.3 with:

sudo apt-get install goaccess

If you are on any Debian based Linux and you want to run the latest (0.9.2) version you can simply run:

wget http://tar.goaccess.io/goaccess-0.9.2.tar.gz
tar -xvzf goaccess-0.9.2.tar.gz
cd goaccess-0.9.2/
sudo apt-get install build-essential
sudo apt-get install libglib2.0-dev
sudo apt-get install libgeoip-dev
sudo apt-get install libncursesw5-dev
./configure --enable-geoip --enable-utf8
make
sudo make install

This will install the software in “/usr/local/bin/” and the manual in “/usr/local/man/”.

Running

Running the software is as easy as:

man goaccess
goaccess -f /var/log/apache2/access.log

The software will prompt you the log format. For me the “NCSA Combined Log Format” log format worked best. For nginx I just ran:

goaccess -f /var/log/nginx/access.log

It is really awesome, try it!

Heka monolog decoder

This post is about how to use heka to give your symfony 2 application logs the care they deserve.

Application logs are very important for the quality of the product or service you are offering.

They help you find out what went wrong so you can explain and fix a bug that was reported recently. Or maybe to gather statistics to see how often a certain feature is used. For example how many bare metal reinstallation requests were issued last month and how many of those failed. Valuable information that you could use to decide what feature you are going to work on next.

At LeaseWeb we use quite a lot of php and Seldaek’s monolog is our logging library of choice. Recently we open sourced a heka decoder on github here. For you who do not know heka yet, check out their documentation.

Heka is an open source stream processing software system developed by Mozilla. Heka is a “Swiss Army Knife” type tool for data processing, useful for a wide variety of different tasks, such as …

Heka runs as a system daemon just like logstash or fluentd. Heka is written in go and comes with an easy to use plugin system based on lua. It has almost no dependencies and is lightweight. James Turnbull has written a nice article on how to get started with heka.

send symfony 2 application logs to elastic search

How better to explain with an example.

Lets say you have a symfony 2 application and you want the application logs to be sent to an Elastic Search platform.

On a debian based os you can download one of the heka debian packages from github.

    $ wget https://github.com/mozilla-services/heka/releases/download/v0.9.2/heka_0.9.2_i386.deb
    $ sudo dpkg -i heka_0.9.2_i386.deb

To configure heka you are required to edit the configuration file located at /etc/hekad.toml.

    $ vim /etc/hekad.toml

Take your time to read the excellent documentation on heka. There are many ways of using heka but we will use it as a forwarder:

  1. Define an input, where messages come from.
  2. Tell heka how it should decode the monolog log line into a heka message
  3. Tell heka how to encode the message so Elastic Search will understand it
  4. Define an output, where should the messages be sent to.

First we define the input:

    [Symfony2MonologFileInput]
    type = "LogstreamerInput"
    log_directory = "/var/www/app/logs"
    file_match = 'prod\.log'
    decoder = "Symfony2MonologDecoder"

Adjust `log_directory` and `file_match` according to your setup. As you can see we alread told heka to use the `Symfony2MonologDecoder` to we will define that one next:

    [Symfony2MonologDecoder]
    type = "SandboxDecoder"
    filename = "/etc/symfony2_decoder.lua"

Change the `filename` with the path where you placed the lua script on your system.

Now we have defined the input we can tell heka where to output messages to:

    [ESJsonEncoder]
    index = "%{Hostname}"
    es_index_from_timestamp = true
    type_name = "%{Type}"

    [ElasticSearchOutput]
    message_matcher = "TRUE"
    server = "http://192.168.100.1:9200"
    flush_interval = 5000
    flush_count = 10
    encoder = "ESJsonEncoder"

In the above example we assume that your Elastic Search server is running at 192.168.100.1.

And thats it.

A simple log line in app/logs/prod.log:

    [2015-06-03 22:08:02] app.INFO: Dit is een test {"bareMetalId":123,"os":"centos"} {"token":"556f5ea25f6af"}

Is now sent to Elastic Search. You should now be able to query your Elastic Search for log messages, assuming the hostname of your server running symfony 2 is myapi:

    $ curl http://192.168.100.1:9200/myapi/_search | python -mjson.tool
    {
        "_shards": {
            "failed": 0,
            "successful": 5,
            "total": 5
        },
        "hits": {
            "hits": [
                {
                    "_id": "ZIV7ryZrQRmXDiB6thY_yQ",
                    "_index": "myapi",
                    "_score": 1.0,
                    "_source": {
                        "EnvVersion": "",
                        "Hostname": "myapi",
                        "Logger": "Symfony2MonologFileInput",
                        "Payload": "Dit is een test",
                        "Pid": 0,
                        "Severity": 7,
                        "Timestamp": "2015-06-03T20:08:02.000Z",
                        "Type": "logfile",
                        "Uuid": "344e7cae-6ab7-4fb2-a770-d2cbad6653c3",
                        "channel": "app",
                        "levelname": "INFO",
                        "bareMetalId": 123,
                        "os": "centos",
                        "token": "556f5ea25f6af"
                    },
                    "_type": "logfile"
                },
        // ...
        }
    }

What is important to notice is that the keys token, bareMetalId and os in the monolog log line end up in Elastic Search as an indexable fields. From your php code you can add this extra information to your monolog messages by supplying an associative array as a second argument to the default monolog log functions:

    <?php

    $logger = $this->logger;
    $logger->info('The server was reinstalled', array('bareMetalId' => 123, 'os' => 'centos'));

Happy logging!

CakePHP flash error message logging

When your CakePHP application cannot handle a submitted form it shows a flash error message (normally a red bar) and some fields in red (validation errors). By default, CakePHP log exceptions and fatal errors to “app/tmp/logs/error.log”. Unfortunately flash error messages and validation errors are not logged by default. This can be explained since the errors are actually handled and can thus be considered “user errors” and not “application errors”. But when a customer needs assistance, you actually need both types of error logs. Note that the Apache access log will also log these requests, but normally this does not provide enough information. In this post we will show how you can add flash error message logging to your CakePHP application.

First we will show that normal error logging is pretty useful. For example, when you call the PHP function “nltobr()” while this function is actually called “nl2br()” it will be logged as expected:

$ cat app/tmp/logs/error.log
2013-06-09 21:54:44 Error: [FatalErrorException] Call to undefined function nltobr()

For flash error message logging we have created a data structure and a CakePHP component that allows you to make a nice overview like this:

runtime_list

Figure 1: List with all pages served with flash error messages

And when you actually view the details of the flash error message you see the following screen:
runtime
Figure 2: Detail page for the table, showing a flash error message

You can clearly see that somebody was trying to edit user 1. The error message was not very descriptive, while the validation errors were pretty clear about the missing data (password).

Instructions

The data structure used is a MySQL database table that can be created by executing the following SQL:

CREATE TABLE `runtime_errors` (
 `id` int(11) NOT NULL AUTO_INCREMENT,
 `created` datetime NOT NULL,
 `ip_address` varchar(255) NOT NULL,
 `method` varchar(255) NOT NULL,
 `url` varchar(255) NOT NULL,
 `referer` varchar(255) NOT NULL,
 `redirect_url` varchar(255) NOT NULL,
 `data` text NOT NULL,
 `validation_errors` text NOT NULL,
 `flash_message` text NOT NULL,
 `user_id` int(11) DEFAULT NULL,
 PRIMARY KEY (`id`),
 KEY `user_id` (`user_id`),
 KEY `created` (`created`),
 CONSTRAINT `runtime_errors_ibfk_1` FOREIGN KEY (`user_id`) REFERENCES `users` (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8;

Now create the following model and save it to “app/Model/RuntimeError.php”:

<?php
App::uses('AppModel', 'Model/App');

class RuntimeError extends AppModel {
  public $displayField = 'url';
  public $belongsTo = array('User');
}

Add the following component code to “app/Controller/Component/ErrorLoggerComponent.php” to log the flash messages:

<?php
App::uses('Component','Controller');

class ErrorLoggerComponent extends Component
{
  public function beforeRedirect(&$controller, $url, $status, $exit) {
    $this->log($controller,$url);
    return parent::beforeRedirect($controller, $url, $status, $exit);
  }

  public function beforeRender(&$controller) {
    $this->log($controller);
    parent::beforeRender($controller);
  }

  public function log(&$controller,$redirectUrl=false) {
    $session = $controller->Session->read();
    $flash = isset($session['Message']['flash'])?$session['Message']['flash']:false;
    $success = isset($flash['params']['class'])?$flash['params']['class']=='success':false;
    if ($flash && $success==false) {
      $controller->User->RuntimeError->create();
      $data = array('RuntimeError'=>array());
      $data['RuntimeError']['method'] = $controller->request->method();
      $data['RuntimeError']['url'] = $controller->request->here;
      $data['RuntimeError']['referer'] = $controller->request->referer();
      $data['RuntimeError']['redirect_url'] = $redirectUrl?Router::url($redirectUrl):'';
      $data['RuntimeError']['data'] = Spyc::YAMLDump($controller->params->data,2,80);
      $data['RuntimeError']['validation_errors'] = Spyc::YAMLDump($this->getErrors(),2,80);
      $data['RuntimeError']['flash_message'] = Spyc::YAMLDump($flash,2,80);
      $data['RuntimeError']['user_id'] = $controller->Auth->user('id');
      $data['RuntimeError']['ip_address'] = $controller->request->clientIp(true);
      if (!$controller->User->RuntimeError->save($data)) {
        throw new InternalErrorException('Could not log action');
      }
    }
  }

  private function getErrors()
  { $validationErrors = array();
    $models = ClassRegistry::keys();
    foreach ($models as $currentModel) {
      $currentObject = ClassRegistry::getObject($currentModel);
      if (is_a($currentObject, 'Model')) {
        if ($currentObject->validationErrors) {
          $validationErrors[$currentObject->alias] =& $currentObject->validationErrors;
        }
      }
    }
    return $validationErrors;
  }
}

Note that you may want to fine-tune the business logic that decides which messages to log (only errors), because the above code will log all flash messages without exception. To load the above component you have to add the “ErrorLogger” to the “$components” array in “app/Controller/AppController.php”:

 public $components = array(
   ...
   'ErrorLogger'=>array()
 );

Dependencies

For writing YAML output from CakePHP we have added “Spyc” to composer.json, which makes our full composer.json file look like this:

{
  "minimum-stability": "dev",
  "config": {
    "vendor-dir": "vendors"
  },
  "repositories" : [
    {
      "type": "package",
      "package": {
        "name" : "cakephp/cakephp",
        "version" : "2.3.5",
        "source" : {
          "type" : "git",
          "url" : "git://github.com/cakephp/cakephp.git",
          "reference" : "2.3.5"
        },
        "bin" : ["lib/Cake/Console/cake"]
      }
    }
  ],
  "extra": {
    "installer-paths": {
      "app/Plugin/DebugKit": ["cakephp/debug_kit"]
    }
  },
  "require" : {
    "php": ">=5.2",
    "cakephp/cakephp" : "2.3.5",
    "cakephp/debug_kit": "2.2.*",
    "mustangostang/spyc": "0.5.*"
  }
}

To achieve the nice looking index and view pages from Figure 1 and 2 you will have to “bake” some views and controllers. Good luck!

Turn off reverse DNS lookups for Apache access logging

If reverse DNS lookups are shown in your Apache access log, while you were expecting (and needing) IP addresses, this post may help.

htaccess ip address block
Figure 1: Example “.htaccess” file for blocking IP addresses

By default IP addresses are logged in the Apache access log “/var/log/apache2/access.log” unless you specify “HostnameLookups On” in “/etc/apache2/apache2.conf” (it is off by default). But if you are restricting access to specific content using an “.htaccess” file with an “allow from” or “deny from” construction this changes. If you have this in your “.htaccess” file IP addresses are logged:


deny from 14.23.32.41

But if you add a comment to the line like this reverse DNS lookups are logged:


deny from 14.23.32.41 # my home ip address

Cause and work-around

This is caused by “mod_authz_host” (which is enabled by default) that kicks in and converts the IP addresses to hostnames. The work-around is to put the comment on the previous line:


# my home ip address:
deny from 14.23.32.41

It also happens when you use a regular expression or a host name (which is more obvious). Plain IP addresses and CIDR notation do not trigger the conversion. Hopefully this post can save you some time.