Tuesday, 29 January 2013

Symfony2 logging application errors to a database table.

Symfony2 + Monolog + Doctrine = Centralized database logs

If you are running a large Symfony 2 based application, you may want to write your application error logs to a central database. There are a few tutorials on the Symfony 2 website regarding writing logs to different outputs (eg: file, email etc), so if you have read those tutorials you will notice some similarities.

I thought it would be handy to collate all of the code I have found across the Internet into a single tutorial about writing all of your application logs to a database table.

The benefits of logging to a database, means you can run multiple servers and have your logs aggregated in a single location - which means easier debugging. Even if you are running a single server application, it doesn't hurt to be prepared - if you have the time..

This bundle can be dropped into your application and once registered should work transparency.

This bundle is located in the following location:

/src/Tools/LogBundle/

Create the bundle registration classes:

/src/Tools/LogBundle/ToolsLogBundle.php

namespace Tools\LogBundle;

use Symfony\Component\HttpKernel\Bundle\Bundle;

class ToolsLogBundle extends Bundle
{
}

/src/Tools/LogBundle/DependencyInjection/ToolsLogExtension.php

namespace Tools\LogBundle\DependencyInjection;

use Symfony\Component\DependencyInjection\ContainerBuilder;
use Symfony\Component\DependencyInjection\Loader\YamlFileLoader;
use Symfony\Component\HttpKernel\DependencyInjection\Extension;
use Symfony\Component\Config\FileLocator;

class ToolsLogExtension extends Extension
{
    public function load(array $configs, ContainerBuilder $container)
    {
        $loader = new YamlFileLoader($container, new FileLocator(__DIR__.'/../Resources/config'));
        $loader->load('services.yml');
    }

    public function getAlias()
    {
        return 'tools_log';
    }
}

Now create the entity/repository classes for storing the logs

/src/Tools/LogBundle/Entity/SystemLog.php

namespace Tools\LogBundle\Entity;

use Doctrine\ORM\Mapping as ORM;

/**
 *
 * @ORM\Entity(repositoryClass="Tools\LogBundle\Entity\SystemLogRepository")
 * @ORM\Table(name="system_log")
 */
class SystemLog
{
    /**
     * @ORM\Id
     * @ORM\Column(type="integer")
     * @ORM\GeneratedValue(strategy="AUTO")
     */
    private $id;

    /**
     * @ORM\Column(type="text", nullable=true)
     */
    private $log;

    /**
     * @ORM\Column(type="text", nullable=true)
     */
    private $serverData;

    /**
     * @ORM\Column(type="string", length=255, nullable=true)
     */
    private $level;

    /**
     * @ORM\Column(type="datetime")
     */
    private $modified;

    /**
     * @ORM\Column(type="datetime")
     */
    private $created;

    /**
     * @ORM\PreUpdate
     */
    public function setModifiedValue()
    {
        $this->modified = new \DateTime();
    }

    /**
     * @ORM\PrePersist
     */
    public function setCreatedValue()
    {
        $this->modified = new \DateTime();

        $this->created = new \DateTime();
    }

    /**
     * Get id
     *
     * @return integer
     */
    public function getId()
    {
        return $this->id;
    }

    /**
     * Set log
     *
     * @param string $log
     * @return SystemLog
     */
    public function setLog($log)
    {
        $this->log = $log;

        return $this;
    }

    /**
     * Get log
     *
     * @return string
     */
    public function getLog()
    {
        return $this->log;
    }

    /**
     * Set serverData
     *
     * @param string $serverData
     * @return SystemLog
     */
    public function setServerData($serverData)
    {
        $this->serverData = $serverData;

        return $this;
    }

    /**
     * Get serverData
     *
     * @return string
     */
    public function getServerData()
    {
        return $this->serverData;
    }

    /**
     * Set level
     *
     * @param string $level
     * @return SystemLog
     */
    public function setLevel($level)
    {
        $this->level = $level;

        return $this;
    }

    /**
     * Get level
     *
     * @return string
     */
    public function getLevel()
    {
        return $this->level;
    }

    /**
     * Set modified
     *
     * @param \DateTime $modified
     * @return SystemLog
     */
    public function setModified($modified)
    {
        $this->modified = $modified;

        return $this;
    }

    /**
     * Get modified
     *
     * @return \DateTime
     */
    public function getModified()
    {
        return $this->modified;
    }

    /**
     * Set created
     *
     * @param \DateTime $created
     * @return SystemLog
     */
    public function setCreated($created)
    {
        $this->created = $created;

        return $this;
    }

    /**
     * Get created
     *
     * @return \DateTime
     */
    public function getCreated()
    {
        return $this->created;
    }
}

/src/Tools/LogBundle/Entity/SystemLogRepository.php

namespace Tools\LogBundle\Entity;

use Doctrine\ORM\EntityRepository;

class SystemLogRepository extends EntityRepository
{
    /**
     * Find the latest logs
     */
    public function findLatest()
    {
        $qb = $this->createQueryBuilder('l');

        $qb->add('orderBy', 'l.id DESC');

        $qb->setMaxResults(200);

        //Get our query
        $q = $qb->getQuery();

        //Return result
        return $q->getResult();
    }
}

Now we configure our service

We define the logic to listen for application errors and call our own log handler.

/src/Tools/LogBundle/Resources/config/services.yml

parameters:
    logger_database.class: Tools\LogBundle\Logger\DatabaseHandler

services:
    monolog.processor.request:
        class: Tools\LogBundle\Processor\RequestProcessor
        arguments:  [ @session ]
        tags:
            - { name: monolog.processor, method: processRecord }
            - { name: kernel.event_listener, event: kernel.request, method: onKernelRequest}

    logger_database:
        class: %logger_database.class%
        calls:
            - [ setContainer, [ @service_container ] ]

    tools.backtrace_logger_listener:
        class: Tools\LogBundle\EventListener\BacktraceLoggerListener
        tags:
            - {name: "monolog.logger", channel: "backtrace"}
            - {name: "kernel.event_listener", event: "kernel.exception", method: "onKernelException"}
        arguments:
            - @logger

Define our request processor

This class can be used to add additional data to the logging record. For example we have access to the session object, we could inspect that object for additional information to log. This could be used for a variety of purposes, eg: adding server data, post data etc..

/src/Tools/LogBundle/Processor/RequestProcessor.php

namespace Tools\LogBundle\Processor;

use Symfony\Component\HttpFoundation\Session\Session;
use Symfony\Bridge\Monolog\Processor\WebProcessor;

class RequestProcessor extends WebProcessor
{
    private $_session;

    public function __construct(Session $session)
    {
        $this->_session = $session;
    }

    public function processRecord(array $record)
    {
        $record['extra']['serverData'] = "";

        if( is_array($this->serverData) ) {
            foreach ($this->serverData as $key => $value) {

                if( is_array($value) ) {
                    $value = print_r($value, true);
                }

                $record['extra']['serverData'] .= $key . ": " . $value . "\n";
            }
        }

        foreach ($_SERVER as $key => $value) {

            if( is_array($value) ) {
                $value = print_r($value, true);
            }

            $record['extra']['serverData'] .= $key . ": " . $value . "\n";
        }

        return $record;
    }
}

Define our backtrace listener

The backtrace always comes in handy, lets configure an event listener to add this to the logger object.

/src/Tools/LogBundle/EventListener/BacktraceLoggerListener.php

namespace Tools\LogBundle\EventListener;

use Symfony\Component\HttpKernel\Log\LoggerInterface;
use Symfony\Component\HttpKernel\Event\GetResponseForExceptionEvent;

class BacktraceLoggerListener
{
    private $_logger;

    public function __construct(LoggerInterface $logger = null)
    {
        $this->_logger = $logger;
    }

    public function onKernelException(GetResponseForExceptionEvent $event)
    {
        $this->_logger->addError($event->getException());
    }
}

Define our database handler

Now we just have to tell our database handler how to save the log to the database table.

/src/Tools/LogBundle/Logger/DatabaseHandler.php

namespace Tools\LogBundle\Logger;

use Monolog\Handler\AbstractProcessingHandler;
use Monolog\Logger;

/**
 * Stores to database
 *
 */
class DatabaseHandler extends AbstractProcessingHandler
{
    protected $_container;

    /**
     * @param string $stream
     * @param integer $level The minimum logging level at which this handler will be triggered
     * @param Boolean $bubble Whether the messages that are handled can bubble up the stack or not
     */
    public function __construct($level = Logger::DEBUG, $bubble = true)
    {
        parent::__construct($level, $bubble);
    }

    /**
     *
     * @param type $container
     */
    public function setContainer($container)
    {
        $this->_container = $container;
    }

    /**
     * {@inheritdoc}
     */
    protected function write(array $record)
    {
        // Ensure the doctrine channel is ignored (unless its greater than a warning error), otherwise you will create an infinite loop, as doctrine like to log.. a lot..
        if( 'doctrine' == $record['channel'] ) {

            if( (int)$record['level'] >= Logger::WARNING ) {
                error_log($record['message']);
            }

            return;
        }
        // Only log errors greater than a warning
        // TODO - you could ideally add this into configuration variable
        if( (int)$record['level'] >= Logger::WARNING ) {

            try
            {
                // Logs are inserted as separate SQL statements, separate to the current transactions that may exist within the entity manager.
                $em = $this->_container->get('doctrine')->getEntityManager();
                $conn = $em->getConnection();

                $created = date('Y-m-d H:i:s');

                $serverData = $record['extra']['serverData'];

                $stmt = $em->getConnection()->prepare('INSERT INTO system_log(log, level, serverData, modified, created)
                                        VALUES(' . $conn->quote($record['message']) . ', \'' . $record['level'] . '\', ' . $conn->quote($serverData) . ', \'' . $created . '\', \'' . $created . '\');');
                $stmt->execute();

            } catch( \Exception $e ) {

                // Fallback to just writing to php error logs if something really bad happens
                error_log($record['message']);
                error_log($e->getMessage());
            }
        }
    }
}

Configure monolog in config

Update your application config to use the new logger. Note: If you are not seeing any logs writing to the database, make sure your dev/prod specific configs are not overriding monolog/handlers/main within the config files.

/app/config/config.yml

monolog:
    handlers:
        main:
            type: service
            level: warning
            id: logger_database
            formatter: monolog.processor.request

Register the bundle in your application

/app/AppKernal.php

class AppKernel extends Kernel
{
    public function registerBundles()
    {
        $bundles = array(
            ...
            new Tools\LogBundle\ToolsLogBundle(),
            ...
        );
    }
}

That's about it..

Your application logs will now be writing to the system_log table within your database.

Some optional features

Use delayed insert

If your database platform supports it, you may want to delay the inserts to the database (as they are most likely a lower priority than other components of your application.

Output the latest logs within your application

You may want to view your logs within an admin section of your application. This again is pretty simple.

Build your controller

/src/Tools/LogBundle/Controller/AdminController.php

namespace Tools\LogBundle\Controller;

use Symfony\Bundle\FrameworkBundle\Controller\Controller;
use Symfony\Component\HttpFoundation\Request;

use Sensio\Bundle\FrameworkExtraBundle\Configuration\Route;
use Sensio\Bundle\FrameworkExtraBundle\Configuration\Template;

/**
 *
 */
class AdminController extends Controller
{
    /**
     * @route("/")
     * @template()
     */
    public function indexAction( Request $request )
    {
        $em = $this->getDoctrine()->getEntityManager();
        $logs = $em->getRepository('Tools\LogBundle\Entity\SystemLog')->findLatest();

        return $this->render('ToolsLogBundle:default:index.html.twig', array(
            'logs' => $logs
        ));
    }
}

Define your bundle route

/src/Tools/LogBundle/Resources/config/routing.yml

tools_log_admin:
    resource: "@ToolsLogBundle/Controller/AdminController.php"
    type: annotation
    prefix: /admin/log

Add this routing file to your primary routing file. 

/app/config/routing.yml

tools_log_bundle:
    resource: "@ToolsLogBundle/Resources/config/routing.yml"

Provide your view (twig) file

/src/Tools/LogBundle/Resources/views/default/index.html.twig

{# extends "YourBundle::layout.html.twig" #}
{% block content %}

        <h1>Logs</h1>

        <table class="table table-striped">
            <thead>
                <tr>
                    <th style="width: 30px;">Id</th>
                    <th style="width: 100px;">Level</th>
                    <th>Log</th>
                    <th style="width: 150px;">Created</th>
                </tr>
            </thead>
            <tbody>
            {% if logs|length > 0 %}
            {% for log in logs %}
                <tr>
                    <td>{{ log.id }}</td>
                    <td>{{ log.log }}</td>
                    <td>{{ log.level }}</td>
                    <td>{{ log.created.format('Y-m-d H:i:s') }}</td>
                </tr>
            {% endfor %}
            {% else %}
                <tr>
                    <td colspan="4">
                    No logs found
                    </td>
                </tr>
            {% endif %}
            </tbody>
        </table>

{% endblock %}

There you have it!

A simple admin page that will show you the latest 200 logs.

The URL will be:
www.yourdomain.com/admin/log

I highly recommend you update your firewall to restrict this page to admin users.

12 comments:

  1. Hi Dion,

    I tried to implement your Bundle, but I get the following error:

    [ErrorException]
    Catchable Fatal Error: Argument 1 passed to Monolog\Handler\AbstractHandler
    ::setFormatter() must be an instance of Monolog\Formatter\FormatterInterfac
    e, instance of Tools\LogBundle\Processor\RequestProcessor given, called in
    ..../app/cache/dev/appDevDebugProjectContainer.php on line 15
    78 and defined in ..../vendor/monolog/monolog/src/Monolog/Han
    dler/AbstractHandler.php line 97

    Do you have an idea what the problem could be?

    ReplyDelete
    Replies
    1. Quickfix: just remove the line "formatter: monolog.processor.request" from your config.yml

      Delete
  2. This comment has been removed by the author.

    ReplyDelete
  3. Hi Dion!

    Thanks for the solution, it's working fine for me!

    DatabaseHandler class however has an extra parameter in phpdoc comment (stream), what was it for?
    /**
    * @param string $stream
    * @param integer $level The minimum logging level at which this handler will be triggered
    * @param Boolean $bubble Whether the messages that are handled can bubble up the stack or not
    */

    Bests,
    Andras

    ReplyDelete
  4. Hi,
    there is something very disturbing. The logger works well on dev and stage environment, however, there is no log on prod with debug turned off or even on.

    the service setup in app/config/config_prod.yml looks like this:

    monolog:
    handlers:
    main:
    type: service
    level: warning
    id: logger_database
    formatter: monolog.processor.request

    and i have changed one thing, change the >= Logger::WARNING to Logger::NOTICE in DatabaseHandler

    now there is no log :(

    ReplyDelete
    Replies
    1. Hi Andras,
      Thanks for letting me know.
      This post was for Symfony2.1 from memory so it's a little out of date. I'll update it with the latest version of Symfony from some newer projects I've worked on in the coming days.
      Dion

      Delete
    2. Thanks Dion, I will check back then..

      I also want to ask monolog developers about the problem, because it seems that the higher level errors (> 200) are not even passed to the database handler, but i cannot figure out, why.. (I've tried it on the same dev server with production env-var with debug turned on and off, but it doesn't log only info level messages into file)

      Delete
  5. Hi @Dion,
    The SQL should be: "INSERT INTO system_log(log, level, serverData (=> server_data), modified, created)"

    ReplyDelete
    Replies
    1. $created = new \DateTime();
      $item = new SystemLog();
      $item->setLog( $record['message'] )
      ->setLevel( $record['level'] )
      ->setServerData( $record['extra']['serverData'] )
      ->setModified( $created )
      ->setCreated( $created );

      $em = $this->_container->get('doctrine')->getEntityManager();
      $em->persist($item);
      $em->flush();

      Delete
  6. Hello, I love reading through your blog, I wanted to leave a little comment to support you and wish you a good continuation. Wish you best of luck for all your best efforts.

    Cross Border Trucking & Vendor Assembly services

    ReplyDelete
  7. This comment has been removed by the author.

    ReplyDelete