Skip to main content

Grokking PHP monolog context into Elastic


An indexed and searchable centralized log is one of those tools that once you've had it you'll wonder how you managed without it. 
 
I've experienced a couple of advantages to using a central log - debugging, monitoring performance, and catching unknown problems.

Debugging

Debugging becomes easier because instead of poking around grepping text logs on servers you're able to use a GUI to contrast and compare values between different time ranges.

A ticket will often include sparse information about the problem and observed error, but if you know more or less when a problem occurred then you can check the logs of all your systems at that time.

Problem behaviour in your application can occur as a result of the services you depend on.  A database fault will produce errors in your application, for example.

If you log your database errors and your application errors in the same central platform then it's much more convenient to compare behaviour between the systems.


I've often found that knowing the application context makes it a lot easier to debug a problem.  I can also more easily reason about the path my code would have taken.  If I'm feeling energetic I can make an attempt to reproduce it and play it back in slow motion with my debugger.

Monitoring performance

Indexing your logs lets you use a query language to search them.  All of the popular logging platforms include a DSL that lets you perform aggregations and other statistical functions on values contained in your logs.

This makes it a lot easier for your team to ask and answer questions about historical behaviour.

You can very easily ask "find me a list of all endpoints that take longer than 0.5 seconds to respond", or "find me all the requests that took longer than two standard deviations above mean to respond to".

Central logging doesn't enable you to answer questions, you could already do that manually.  Central logging makes it easy to answer questions, which encourages you to ask more of them.

Being able to query patterns makes it easier to identify client use patterns that are harmful to your server.  This lets you mitigate them on either the server or the client.

You could notice, for example, that a client is not respecting your cache control headers and is performing a repeat call to the API when it should be relying on a local cache.  This lets you engage the client developers with alternatives and SDK's to help them take advantage of your caching strategy.

Managing verbosity and unknowns

Anomaly detection is a powerful addition to central logging.  Logging is great for analyzing historical performance, but is too verbose to be useful for monitoring in any level of detail. 

Machine learning algorithms can analyze your logs and find outliers in message frequency or values.  They can do this quite cheaply in real time after an initial learning process.  Your central logs can become an early warning system for problems that your customers haven't reported yet.

I'm a fan of Unomaly, but there are lots of other options out there, Splunk and Elastic both include machine learning options for example.

A PHP implementation

So now that you're convinced that central logging will improve your debugging, allow you to identify performance bottlenecks, and make auditing more convenient what is the next step in your PHP project?

Monolog is the de facto standard PHP logging library. Part of its fancy features include the ability to log a contextual array of information, which is provided as a second parameter, like this:

$log->info("Example of something being logged", $visitDetails);

This results in the array being output as a JSON string at the end of your log message and can be very useful indeed.

Some examples of the useful information you can put in the context could be a request id that lets you group log entries from any particular request.  You'd assign a request a unique id when you first start processing it, and then consistently include this id in your logs.

Monolog lets you push logs straight into Elastic, but if we push our logs to a local logstash instance then we save ourselves some network I/O and allow for some buffering in the event that Elastic is down.

Logstash also lets you grok your logs and massage them into a form that Elastic can understand.

Actually writing the grok pattern is a lot like writing a regex pattern, but luckily there are some tools that will greatly speed this up for you.

Take a look at:
  1. https://grokdebug.herokuapp.com/
  2. https://github.com/logstash-plugins/logstash-patterns-core/blob/master/patterns/grok-patterns
  3. https://github.com/kkos/oniguruma/blob/master/doc/RE
Oniguruma lets you use regex in the Grok pattern, like this: (?<field_name>the pattern here)

For my out of the box installation of Monolog the logstash configuration looked like this:

The aim here is to use grok to tokenize your log line into fields. You can then use the json filter to further expand any json fields that you've grokked.

In my example the field "context" is grokked from the context that can be added as "extra data". See the Monolog manual for details.


I was able to get Monolog to push logs to Logstash by using a SockerHandler, like this:

When you mix this up with AWS managed Elasticsearch (and their plugin) you can very quickly get up and running with Kibana.

Example repository is at https://github.com/andybeak/monolog-elk-demo


Comments

Popular posts from this blog

Using Fail2Ban to protect a Varnished site from scrapers

I'm using Varnish to cache a fairly busy property site.  Varnish works like a bomb for normal users and has greatly improved our page load speed. For bots that are scraping the site, presumably to add the property listings to their own site, though the cache is next to useless since the bots are sequentially trawling through the whole site. I decided to use fail2ban to block IP's who hit the site too often. The first step in doing so was to enable a disk based access log for Varnish so that fail2ban will have something to work with. This means setting up varnishncsa.  Add this to your /etc/rc.local file: varnishncsa -a -w /var/log/varnish/access.log -D -P /var/run/varnishncsa.pid This starts up varnishncsa in daemon mode and appends Varnish access attempts to /var/log/varnish/access.log Now edit or create /etc/logrotate.d/varnish and make an entry to rotate this access log: /var/log/varnish/*log { create 640 http log compress ...

Translating a bit of the idea behind domain driven design into code architecture

I've often participated in arguments discussions about whether thin models or thin controllers should be preferred.  The wisdom of a thin controller is that if you need to test your controller in isolation then you need to stub the dependencies of your request and response. It also violates the single responsibility principal because the controller could have multiple reasons to change.   Seemingly, the alternative is to settle on having fat models. This results in having domain logic right next to your persistence logic. If you ever want to change your persistence layer you're going to be in for a painful time. That's a bit of a cargo cult argument because honestly who does that, but it's also a violation of the single responsibility principal.   One way to decouple your domain logic from both persistence and controller is to use the "repository pattern".   Here we encapsulate domain logic into a data service. This layer deals exclusively with imple...