As part of my ongoing research into big-data visualisation and infrastructure and application management tools it\u00a0came to give ELK<\/a> a test run to check\u00a0if it’s suited to my needs. I’ve already looked at a few others (which I will detail in another article), and so far haven’t found somethings suitable for a SMB to collate and process both “live” information from applications, e.g. from existing databases or APIs, combined with “passive” information from log files.<\/p>\n Some of the applications I work with are modifiable so\u00a0we can take advantage of APIs to push event-driven data out to analytics or monitoring platforms, but some legacy components are just too hard to upgrade thus\u00a0log-scraping could be the only viable option.\u00a0I already use tools at various stack levels such as New Relic (APM), Datadog\/AWS (infrastructure), Google Analytics (web\/user) and my special interest: custom business-event monitoring. Ideally these various sources could be combined to produce\u00a0some extremely powerful emergent information, but the tools at these different levels are often specific to the needs of that level such as hardware metrics vs. user events and thus difficult to integrate.<\/p>\n My Experiences Trialling Elastic\u00a0<\/strong><\/p>\n It seemed from an initial look that the Elastic stack was flexible and agnostic enough to be able to provide any of these aspects. But would it be a jack-of-all and master-of-none?<\/p>\n To give it a go, I looked at the three main components separately at first. Simply put:<\/p>\n The\u00a0provide\u00a0hosted services\u00a0but I didn’t feel like\u00a0committing just yet\u00a0and didn’t want to be rushed in a limited-time trial, so\u00a0I downloaded and installed the servers\u00a0locally. I mentally prepared myself for hours of installation and dependency hell\u00a0after my experiences with Graphite and Datalab.<\/p>\n But – these were my only notes<\/em> during the fantastically quick set-up:<\/p>\n I just unzipped it and ran it and it worked. I know that’s how the world should work<\/em>, but this is the first time I’ve experienced that for years.<\/p>\n Interest piqued, I decided to run through the tutorials and then move on to setting up a real-world log import scenario for a potential client. I noted down the\u00a0things I discovered,\u00a0hopefully they will help other people on a similar first journey. At least it\u00a0will help me when I return to this later and have predictably forgotten it all.<\/p>\n LogStash<\/b> – data acquisition pipeline<\/p>\n I ran through the Apache logs tutorial<\/a>, after completing the basic demos<\/a>.<\/p>\n The default index of logstash-output-elasticsearch<\/a> is “logstash-%{+YYYY.MM.dd}”, this is not mentioned in the tutorials. Thus all Apache logs are indexed under this, hence the default search like I don’t think this will be useful in reality – having an index for every day, but I guess we’ll get to that later.\u00a0Furthermore the timestamp imported\u00a0is today’s<\/span>\u00a0date, i.e. the time of the import, not the time parsed from the logs. [I will\u00a0address\u00a0this later, below]<\/em><\/p>\n Interesting initial API calls to explore:<\/p>\n http:\/\/localhost:9200\/_cat\/indices?v<\/a> – all (top level) indices, v = verbose, with headers.<\/p>\n http:\/\/localhost:9200\/_cat\/health?v<\/a> \u00a0 – like Apache status<\/p>\n http:\/\/localhost:9200\/_cat\/ <\/a>– all top level information<\/p>\n Grok<\/b> – import parser<\/p>\n Grok is one of the most important filter\u00a0plugins<\/a>– enabling you to parse any log file format, standard or custom. So I quickly tried to write an\u00a0info\u00a0<\/em>trace log<\/i> grok filter for some legacy logs I often analyse manually and thus\u00a0know very well. This would make it easier to evaluate the quality and depth\u00a0of the tools – “how much more will these tools let me see?”<\/p>\n My first noobish attempt was an “inline” pattern in the Grok configuration. A toe in the water.<\/p>\n I found it hard to debug at first: it wasn\u2019t importing but I saw no errors. This was because it was working!\u00a0<\/i>It took me a little while to get the trial-and-error configuration debug cycle right. Tips:<\/p>\n OK. I got my custom log imported fairly easily – but how to I access it?<\/p>\n Elastic Search – <\/b>search engine & API<\/p>\n During my first 5 minutes going through the ES tutorials\u00a0and I noted:<\/p>\n Great – the REST API looks really good, easily explorable with every feature I had hoped for and more. The “scores” aspect made me realise that this isn’t just a data API, this is a proper search engine too, with interesting features such as fuzziness and Levenshtein distances. I hadn’t really thought of using that – from a traditional data accuracy perspective this seemed\u00a0all a bit too gooey, but\u00a0perhaps there will be a niche I could use it for.<\/p>\n Kibana – <\/b>for visualisations<\/p>\n So again great, this was “too easy” to get up and running, literally within 5 minutes I was exploring the data from the Apache tutorial in wonderful technicolor.<\/p>\n So after a broad sweep I was feeling good about this stack so I felt it was time to go a bit deeper.<\/p>\n Mappings<\/b><\/p>\n It seems the next (it should have been first!<\/em>) major task is to map the fields to types, else they all end up as fieldname<\/em>.raw as strings.<\/p>\n But…\u00a0you cannot change mappings<\/a>\u00a0on existing data – so you must set them up first! However you can create a new index, and re-index the data\u2026 somehow, but I found it easier to start again for the moment.<\/p>\n I couldn’t figure out (or there isn’t) a\u00a0mini-language for a GET to create mappings, so I used the example CURL commands which weren’t as annoying as I’d thought they’d be –\u00a0except I do use my browser URL history as my memory. It’s just a bit harder to re-edit and re-use SSH shell histories, than in-browser URLs.<\/p>\n <\/p>\n Getting the date format right\u2026<\/b><\/p>\n The legacy server,\u00a0from which these logs came,\u00a0doesn\u2019t use a strict datetime format (sigh), and\u00a0 Logstash was erroring.<\/p>\n Initially I tried to write\u00a0a \u201cCustom Pattern\u201d but then I found the Grok date property format should<\/em> be able to handle it, even with 2 digits of microseconds (default is 3 digits). To figure this out, I had to manually traverse the tree of patterns\u00a0in the core library<\/a>\u00a0from DATESTAMP down through its children. This was actually a good exercise to learn how the match patterns work – very much\u00a0like an NLP grammar definition (my AI degree is all coming back to me).<\/p>\n So why is Grok erroring when the pattern is correct?<\/p>\n It took me a while to realise it’s because the Grok DATESTAMP pattern is just a regexp to parse\u00a0the message data into pieces but\u00a0is more permissive<\/em> than the default date field mapping specification in the subsequent Elasticsearch output stage. So it tokenises the date syntactically, but it\u2019s the field mapping which then tries to interpret it semantically which\u00a0fails.<\/p>\n OK, so I felt\u00a0I should write a custom property mapping to accommodate the legacy format.<\/p>\n Mild annoyance alert: To do these changes I had to keep re-creating the indexes and changing the output spec, restarting Logstash and changing my debug query URLs. So it’s worth\u00a0learning how to re-index data, or (when doing it for real) get this right first in an IA scoping stage.<\/p>\n Tip: I debugged this\u00a0by pasting very specific single logs one line at a time into the test.log file which Logstash is monitoring. Don\u2019t just point it a huge log file!<\/i><\/p>\n So many formats!<\/strong><\/p>\n The date mappings are in yet another<\/i> language\/specification\/format\/standard called Joda<\/a>. At this point I started to feel a little overwhelmed with all the different formats you need to learn to get a job done. I don\u2019t mind learning a format, but I\u2019m already juggling three or four new syntaxes and switching between them when I realise I need to move a filtering task to a different layer is an off-putting mix of laborious and confusing.<\/p>\n For example I just learned how to make optional matches in Grok patterns, but I can\u2019t apply it here and do \u201cHH:mm:ss.SS(S)?\u201d to cope with log-oddities, which is a frustrating dead-end for this approach. So I have to look again at all the other layers to see how I can resolve this with a more flexible tool.<\/p>\n OK, once the date mapping works\u2026 it all imports successfully.<\/p>\n Creating\u00a0Kibana visualisation<\/strong><\/p>\n To use this time field you create a new index pattern in <\/i>Kibana>Settings>Indices and select the \u201cdate\u201d field above as the \u201cTime-field name\u201d, otherwise it will use the import<\/i> time \u00a0as the timestamp – which won\u2019t be right when we\u2019re importing older logs. (It will be almost<\/i> right if\u00a0logs are being written and processed immediately but this won’t be accurate enough for me).<\/p>\n I loaded in a few hundred thousand logs, and viewed them immediately in Kibana\u2026 which looks good! There are immediately all the UI filters from my dreams, it looks like it will do everything I want.<\/p>\n But there\u2019s an easier way!<\/strong><\/p>\n The Date filter<\/a> allows you to immediately parse a date from a field into the default @timestamp field.\u00a0\u201cThe date filter is especially important for sorting events and for backfilling old data.<\/i>\u201d which is exactly what I’m doing.<\/p>\n So I made a new filter config:<\/p>\n And it turned up like this (note: without using the field mapping above, so the redundant \u201cdate\u201d property here is just a string). Also note the UTC conversion, which wqs a little confusing\u00a0at first especially as I unwittingly\u00a0chose a to test a\u00a0log\u00a0across the rare 29th of Feb!<\/p>\n The desired result was achieved: this showed up in Kibana instantly<\/em>, without having to specify a custom time-field name.<\/p>\n I got it wrong initially, but at least that helped me to understand what these log-processing facilities\u00a0are saving you from having to do later (possibly many times).<\/p>\n Making more complex patterns<\/b><\/p>\n The legacy log format I’m trialling has typical info\/warning\/error logs, but each type also has a mix of a few formats for different events.\u00a0To break down these various log types, you need\u00a0to implement a\u00a0grammar tree of expressions in custom\u00a0Grok Patterns.<\/p>\n The first entries should be the component \u201celements\u201d such as verbose booleans or enumerations<\/p>\n If a log file has various entry types, like sent\/received, connection requests and other actions then the next entries should be matching the various log-line variants composed of those custom elements and any standard patterns from the core libraries. Then finally you have one log-line super-type which matches any log-line variants Again the tools mentioned above were crucial in diagnosing the records which arrive in Elasticsearch tagged with _grokparsefailure while you are developing these patterns.<\/p>\n For annoyingly \u201cflexible\u201d legacy log formats I found these useful:<\/p>\n Differentiating log variants in the resulting data<\/b><\/p>\n Next I wanted to be able to differentiate which log-line variant each log had actually matched. This turned out to be harder than I had thought. There doesn\u2019t seem to be a mechanism within the regular-expression matching capabilities of the Grok patterns such as to be able to \u201cset a constant\u201d when a specific pattern matches.<\/p>\n The accepted method is to use logic in the pipeline configuration file plus the abilities to add_tags or add_fields in the Grok configuration. This approach is sadly a bit wet (not DRY) as you have to repeat the common configuration options for each variant. I tried to find other solutions, but currently I haven\u2019t resolved the repetitions. However this can also result in a false _grokfailure tag, because the two configurations are run sequentially<\/em>, regardless of a match. So if the first one matches, the second will fail.<\/p>\n One solution<\/a> is to use logic to check the results of the match as you progress.<\/p>\n This works well, and for these log-line variants, I\u2019m now getting a \u201cconnection\u201d tag, which can enable API queries\/Kibana to know to expect a totally different set of properties for items in the same index. I see this tag as a kind of \u201cclassname\u201d – but I don\u2019t know yet if I\u2019m going down the right road with that OO thought train!<\/p>\n Another method<\/a> is to \u201cpre-parse\u201d the message and only perform certain groks for specific patterns. But again it still feels like this is duplicating work from the patterns.<\/p>\n Even with the conditional in place above,\u00a0the first filter technically fails before the second one succeeds. This means the first failure will still<\/span> add a \u201c_grokparsefailure\u201d tag to an eventually successful import!<\/p>\n The final workaround is to manually remove the failure tags in all but the last<\/i> filter:<\/p>\n So while I am still very impressed with the ELK stack, I am starting to see coping with real-world complexities isn’t straightforward and is leading to some relatively hacky and unscalable techniques due to the limited configuration language. It’s these details that will sway people from one platform to another, but it’s difficult to find those sticking points until you’ve really fought with it – as Seraph so wisely put it.<\/p>\n Loading up some “big” data<\/b><\/p>\n Now I was ready to import a chunk\u00a0of old logs and give it a good test run. I have a lot – a lot – of potential archive data going back years. It seemed to import fairly quickly even on my old 6yr-old MacBookPro Logstash chewed 200,000 logs into Eleasticsearch in a few\u00a0minutes. (I know this is tiny data, but it’s all I had in my clipboard at the time.) I’m looking forward to testing millions of logs on a more production tuned server and benchmarking it with proper indexing and schema set up.<\/p>\n Heading back to Kibana, I was able to explore the data more thoroughly now it\u2019s a bit more organised. The main process goes through:<\/p>\n This process is intuitive and exactly what you want to do. You can explore the data by building queries with the help of the GUI, or hand-craft some of it with more knowledge of the Elasticsearch API, then you can save these queries for re-use later in the visualisation tools.<\/p>\n Even in the default\u00a0charts, I instantly saw some interesting patterns including blocks of missing data which looked like a server outage, unusual spikes of activity, and the typical camel-humps of the weekend traffic patterns. These patterns are difficult to spot in the raw logs, unless you have Cipher eyes.<\/p>\n I had a quick look at the custom visualisations, particularly the bar-charts, and found you can quite easily create sub-groups from various fields and I started to realise how powerful the post-processing capabilities of Kibana could be in slicing up the resulting data further.<\/p>\n Summary thoughts<\/b><\/p>\n In summary I feel the ELK stack can certainly do what I set out to achieve – getting business value out of gigabytes of old logs and current logs without having to modify legacy servers. I feel it could handle both infrastructure level monitoring and the custom business-events both stored in logs and fired from our APIs and via MQs. <\/p>\n The component architecture and exposed REST API is also flexible enough to be able to easily feed\u00a0into other existing data-processing pipelines instead of Kibana, including my latest pet-project Logline<\/a>\u00a0which visualises mashups of event-driven logs from various sources using the Vis.org<\/a> Timeline.<\/p>\n Next steps<\/b><\/p>\n I feel now I\u2019m ready to present this back to the folks at the organisations I consult for and confidently offer it as a viable solution. It offers tools for building a business intelligence analysis platform and with the addition of the monitoring tools such as Watcher potentially bring that post-rational intelligence into real-time.<\/p>\n Beyond that – the next step could even be predicting the future, but that\u2019s another story.<\/p>\n","protected":false},"excerpt":{"rendered":" As part of my ongoing research into big-data visualisation and infrastructure and application management tools it\u00a0came to give ELK a test run to check\u00a0if it’s suited to my needs. I’ve already looked at a few others (which I will detail … Continue reading \n
\n
\n
http:\/\/localhost:9200\/logstash-2016.07.11<\/b>\/_search?q=response=200<\/code><\/p>\nfilter {\r\n\u00a0\u00a0\u00a0grok {\r\n\r\n # example 01\/03\/2016 23:59:43.15 INFO: SENT: 11:59:43 PM DEVICE:123:<COMMAND>\r\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 match => { \"message\" => \"%{DATESTAMP:date} %{WORD:logType}: %{WORD:direction}: %{TIME} %{WORD:ampm} DEVICE:%{INT:deviceId}:%{GREEDYDATA:command}\"}\r\n\u00a0\u00a0\u00a0}\r\n}\r\n<\/pre>\n\n
\n
http:\/\/localhost:9200\/logstash-2016.07.12\/_search?q=deviceId:1234&response=200&pretty<\/code><\/li>\n&_source=logType,direction,command<\/code><\/li>\n\n
\n
curl -XPUT http:\/\/localhost:9200\/ra-info-tracelog -d '\r\n{\r\n\u00a0\"mappings\": {\r\n\u00a0\u00a0\u00a0\"log\": {\r\n\u00a0\u00a0\u00a0\u00a0\u00a0\"properties\": {\r\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\"date\": { \"type\" : \"date\" },\r\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\"deviceId\": { \"type\" : \"integer\" }\r\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0}\r\n\u00a0\u00a0\u00a0\u00a0\u00a0}\r\n\u00a0\u00a0\u00a0}\r\n\u00a0}\r\n}\r\n';\r\n<\/pre>\n# example 01\/03\/2016 23:59:43.15<\/code><\/p>\n \"date\": {\r\n \"type\" : \"date\" ,\r\n \"format\": \"dd\/MM\/yyyy HH:mm:ss.SS\"\r\n },\r\n<\/pre>\nfilter {\r\n grok {\r\n match => { \"message\" => \"%{DATESTAMP:date} ... \u201c}\r\n }\r\n date {\r\n match => [\"date\", \"dd\/MM\/yyyy HH:mm:ss.SS\"]\r\n }\r\n}\r\n<\/pre>\n \"@timestamp\" : \"2016-02-29T13:00:23.600Z\",\r\n \"date\" : \"01\/03\/2016 00:00:23.60\",\r\n<\/pre>\n
\u00a0 \u00a0 ONOFF (?:On|Off)<\/code>
\n\u00a0 \u00a0 LOG_TYPE (?:INFO|WARNING|ERROR|DEBUG)<\/code>.<\/p>\n
\ne.g.<\/p>\n# e.g. 01\/02\/2016 01:02:34.56 INFO: Connection request: device:1234 from 123.45.56.78:32770 ()\r\nINFO_CONNECTION_REQUEST %{DATESTAMP:date} %{LOG_TYPE:logType}: Connection request: device:%{INT:deviceId} from %{HOSTPORT:deviceIP} \\(%{HOSTNAME}\\)\r\n<\/pre>\n
\ne.g.:<\/p>\nINFO_LINE %{INFO_COMMAND}|%{INFO_CONNECTION_REQUEST}|%{INFO_CONNECTION_CLOSED}|%{INFO_STATUS}\r\n<\/pre>\n\n
( exp<\/i> )?<\/code>\u00a0 \u00a0 \u00a0 \u00a0 \u00a0 e.g. (%{HOSTNAME})?<\/code><\/li>\n\\(%{INT:userId}\\)<\/code><\/li>\n(?: exp<\/i> )<\/code> e.g. (?:INFO|WARNING|ERROR|DEBUG)<\/code><\/li>\n<\/ul>\n
\ne.g.<\/p>\ngrok {\r\n match => { \"message\" => \"%{INFO_CONNECTION_CLOSED}\" }\r\n patterns_dir => [\"mypatterns\"]\r\n add_tag => [ \"connection\" ]\r\n}\r\ngrok {\r\n match => { \"message\" => \"%{RA_INFO_LINE}\" }\r\n patterns_dir => [\"mypatterns\"]\r\n}\r\n<\/pre>\n grok {\r\n match => { \"message\" => \"%{INFO_CONNECTION_CLOSED}\" }\r\n patterns_dir => [\"mypatterns\"]\r\n add_tag => [ \"connection\" ]\r\n }\r\n if (\"connection\" not in [tags]) {\r\n grok {\r\n match => { \"message\" => \"%{INFO_LINE}\" }\r\n patterns_dir => [\"mypatterns\"]\r\n }\r\n }\r\n<\/pre>\n \"@timestamp\" : \"2016-02-29T13:00:25.520Z\",\r\n \"logType\" : [ \"INFO\", \"INFO\" ],\r\n \"deviceId\" : [ \"123\", \"123\" ],\r\n \"connection_age\" : [ \"980\", \"980\" ],\r\n \"tags\" : [ \"connection\" ]\r\n<\/pre>\n
if [message] =~ \/took\\s\\d+\/ { grok { ... } }\r\n<\/pre>\n grok {\r\n match => { \"message\" => \"%{INFO_CONNECTION_CLOSED}\" }\r\n add_tag => [ \"connection\" ]\r\n # don't necessarily fail yet...\r\n tag_on_failure => [ ]\r\n }\r\n<\/pre>\n\n