Power of graylog2 web interface

I was overwhelmed by the power of the graylog2 web interface, after the backend switched to elasticsearch. With custom fields in the gelf message holding valuable data and elasticsearch providing the right kind of search capabilities, its up to the imagination of users on what could be achieved.

Let me take you through a overview of how we could use graylog2 web interface. The rest of the blog assumes, that you have read the previous blog on logstash and graylog.

Armed with custom fields, lets take a common scenario where we want to quickly find out broken urls. We can login to the graylog2 web interface. Once logged in, there will be the messages tab that will be highlighted by default and it shows quick filter.

Now click on the ‘quickfilter‘ option. Select ‘Add additional field‘ from the expanded options.

Enter ‘_response‘ in the first text box and the value ‘404‘ in the next text box. Now hit ‘Run filter’. There you go, the list of all broken urls. You can select the message from the result and on the right side shows the details of the message.

Each of the fields value is clickable, that means you can quickly filter out all the messages with that value. For example, you have found that a old url is hit and it has returned 404. Just select the value in the field request and you will be taken to the results page which lists all messages with the same request url.

You want to know the referrers for all the requests which has this url. We can use the analytics shell to figure this out.

all.distribution({_httpreferrer}, _request = "/old_url")

We would typically go to the analytics tool like Google Analytics to figure out, what browsers were used to reach the site and the number of requests for each of these browsers. This can be mined from the log itself by using the analytics shell with a simple query:

all.distribution({_httpuseragent})

Similarly to find the incoming referral urls and the request count per referral url we can use something like:

all.distribution({_httpreferrer})

With the graylog custom fields we have defined in the previous post, we can find the rendering time for a rails view template, time taken for a rails action, etc.. We could easily enhance it to add fields for queries and their execution time. If that is done, the log can provide vital clues into application performance and behavior of the user.

Just to give a idea of the power that is available, let me quote a real incident. We had a interesting user, who entered a secret information in the designated field, but reported that the private info is compromised and it is shown in another public field. We were clueless how on earth, this could occur. Finally, log mining came to our rescue. we figured out all the requests from that day by that user and then used the rails unique request id of each of these requests and got all the logs. we matched the httpreferrer of a particular request with the request field of other requests, by which we got the exact user flow in the application. Once that is done, we replicated the exact scenario and found that, when a validation error occurs, the focus was not set properly. This debugging was a very simple exercise, since we were able to map the exact user journey in the application. Other wise it would have been a daunting task to figure out what was happening.

From here on, its just about imagination about how much value you want to derive out of your logs and how you want that achieved. The tools are available right at your doorsteps.

After using the tool extensively, there is only one request to graylog team, to look at providing a plugin architecture for the graylog web interface for extension. Also planning to work on Graylog web ui to give some more power and customization capabilities, when time permits.

In case of questions, pls do reach out through twitter or through comments.

logstash + graylog2 – cant ask more for logging

Everyone knows how important logging is for a web application. It is a shelter we build for the rainy day. But the logs in all the application has enormous amount of valuable information, that can give interesting perspectives about the application. Also as applications grow in complexity and scale, logs become spread across multiple machines and files. Soon developers/support people will be overwhelmed by the sheer number of log files to search and track issues. In order to overcome this situation, and to have a clear, simplified oversight over the system, a central logging system becomes necessary.

Was part of a team which was responsible for building a highly distributed and complex system. Just to give a idea of the kind of complexity involved, let me give a brief summary of tech components. The project was developed using three languages (1 dynamic and 2 static), uses sql and a nosql db, a queuing engine, etc.. In order to get the log consolidated and have a central view, we evaluated splunk. Unfortunately it was extremely costly. So we were forced to look at open source alternatives and finally we selected logstash and graylog.

Looking back at that decision, was one of the great decisions. I will share some insights into how logstash and graylog2 could be configured.

First we need to download the logstash jar to each of the machines where log files are generated.
Then we need to configure the input file for logstash to process. its pretty simple. we need to provide the path to files and also group them under different types.

input {
  file {
    type => nginx_web
    path => ["/opt/nginx/logs/access.log", "/opt/nginx/logs/error.log"]
  }
}

Graylog uses a log format called Graylog Extended Log Format(GELF). By using this format, we can send custom fields with the log. This format also doesnot have a log size limitation. We can preprocess the logs and define custom fields based on the line logged, before they are sent to the graylog server. Below is a example of nginx log being parsed using grok patterns(regular expressions) and fields are defined with the values matched. Grok patterns are extremely powerful, so they need a separate detailed blog… but thats for later.

filter {
 grok {
   type => nginx_web
   pattern => "%{IP:clientip} (?:%{HOST:clienthost}|-) (?:%{USER:clientuser}|-) \[%{HTTPDATE:time}\] \"(?:%{WORD:verb} %{URIPATHPARAM:request} HTTP/%{NUMBER:httpversion}|%{DATA:unparsedrq})\" %{NUMBER:response} (?:%{NUMBER:bytes}|-) %{QUOTEDSTRING:httpreferrer} %{QUOTEDSTRING:httpuseragent}"
 }
}

The corresponding nginx log format is:

log_format  main  '$remote_addr $host $remote_user [$time_local] "$request" $status $body_bytes_sent "$http_referer" "$http_user_agent" $ssl_cipher $request_time';

Above grok filter will parse each log entry and fill the values for the following fields clientip, clienthost, clientuser, time, verb, request, httpversion, unparsedrq, response, bytes, httpreferrer, httpuseragent.

The advantage of splitting the input log entry into multiple fields, is that custom rules to search, group can be done on each of these fields in the graylog2 web.
Sample grok pattern for the rails 3 project is:

 grok {
   type => app
   pattern => "\[%{WORD:requesttoken}\] \[%{IP:clientip}\] (?:%{DATA:logstmt}|-)"
 }
 grok {
   type => app
   pattern => "Rendered %{DATA:renderedtemplate} \(%{DATA:rendertime}\)"
 }

The above grok filter parses the rails 3 app log and defines the following fields: requesttoken, clientip, logstmt, renderedtemplate, rendertime.

Next we need to configure the output. This is where we specify the output format as gelf and the graylog server to contact.
We can also specify custom fields. Here we are sending a custom field named environment with value as ‘uat’.
Another predefined field in gelf format is ‘facility’ and here we are setting it with the value of field ‘type’.

output {
 gelf {
 host => "graylog-server-ip"
 facility => "%{@type}"
 custom_fields => ["environment", "uat"]
 }
}

A complete sample configuration for logstash agent is:

input {
  file {
    type => pg91
    path => ["/var/lib/pgsql/9.1/pgstartup.log", "/var/lib/pgsql/9.1/data/pg_log/*.log"]
  }
  file {
    type => app
    path => ["/app/employeemgmt/shared/log/uat.log"]
  }
  file {
    type => nginx_web
    path => ["/opt/nginx/logs/access.log", "/opt/nginx/logs/error.log"]
  }
}

filter {
 grok {
   type => nginx_web
   pattern => "%{IP:clientip} (?:%{HOST:clienthost}|-) (?:%{USER:clientuser}|-) \[%{HTTPDATE:time}\] \"(?:%{WORD:verb} %{URIPATHPARAM:request} HTTP/%{NUMBER:httpversion}|%{DATA:unparsedrq})\" %{NUMBER:response} (?:%{NUMBER:bytes}|-) %{QUOTEDSTRING:httpreferrer} %{QUOTEDSTRING:httpuseragent}"
 }
 grok {
   type => app
   pattern => "\[%{WORD:requesttoken}\] \[%{IP:clientip}\] (?:%{DATA:logstmt}|-)"
 }
 grok {
   type => app
   pattern => "Rendered %{DATA:renderedtemplate} \(%{DATA:rendertime}\)"
 }
}

output {
 gelf {
 host => "graylog-server-ip"
 facility => "%{@type}"
 custom_fields => ["environment", "uat"]
 }
}

All these configuration need to be done in a conf file.
Once the conf file is ready, we need to install the graylog2 server. Installation is pretty simple, again download the server jar file and run it. This graylog2 wiki will help you with that.
Finally we need to start the logstash agent using:

java -jar logstash-1.1.0-monolithic.jar agent -f logstash-agent.conf

Enjoy all your logs are in central Graylog2 server. Watch out for the next post on graylog2 web interface and how we can use it.

Visit to a Eye practice

Thanks to Dr. Harris, we were visiting a pretty large eye practice in United States, to understand the day to day operations.

At the start, we had a perception that a set of tests are done by Technicians in various rooms and collated for the doctor to prescribe the medication. As Dr. Harris took us from room to room giving a brief explanation of what that tests are and how they are done, we were taken back by the speed and efficiency in which they operate a eye clinic.

A common clinical scenario enacted was:

One of our colleagues volunteered to be the patient. He was taken to the front desk where he would register his arrival as per his appointment.
The patient would then be given a small electronic token, which will aid as a directing device too.

So as per the directions of the device, the patient will be waiting in the area mentioned. A paper would be printed in the technician desk automatically which will inform the arrival of the patient.

The technician will then meet the patient take him to the room where he registers his primary eye problem and other medically relevant details.

Then the technician takes the patient to the dilation room from where after few minutes will move in to the exam/ test rooms.

The technician then performs the exams, records the details too in the same paper booklet where previous details are captured. Then the technician leaves the records in his desk, in the designated area “For Dr. Review”.

Dr. Harris once he completes the previous patient, comes to the technician desk and takes the next record available and goes into the corresponding exam room where the patient is waiting.

Dr. Harris does additional exams as necessary. In our clinical scenario, Dr. Harris did about 6 exams on the patient, in less than 40 seconds. Based on clinical findings, a technician stepped in to help the doctor on checking the corneal thickness. This test was also completed before we(as viewers) could assimilate them.

Upon completion of the exam, Dr. Harris prescribed the glasses prescription in the same record and coded the service which he rendered to the patient.

For readers benefit, Coding is the process by which doctors select pre-defined billing codes for each of the service they rendered. This is a standard followed across US, for medical insurance claims.

Then Dr. Harris places the record in the designated area named “visit completed”, from there the technician/administrator takes care of the post visit activities.

One of the most startling thing was the speed in which doctors and technicians capture the data is beyond our imagination. A patient visit will be taking anywhere between 20 mins – 30 mins (actual time spent with doctor and technician). Getting a system to work on these highly efficient practices will be a extremely tough task.

The final question that remains in my mind is:
Can technology bring more efficiency in these environments ?
Without real innovation, I doubt.

However, Technology can improve the quality of health care by:
1. Increasing the legibility of the medical records.
2. Data mining to analyse effective and ineffective practices.
3. Doctors can easily browse through historical data to understand and provide best care possible.
4. Can enhance communication between medical professionals.
Ex: E-Prescribition tracks the patients medications and allergies.
5. Aiding medical professionals to reduce errors

About Dr. Jeff Harris
Jeff Harris is the Vice President of Integrity Digital Solutions and has served on the faculty at the Scott & White Eye Institute for more than eight years. He is actively involved in resident education and lectures regularly on optics and contact lens topics. He provides primary care services and has extensive experience managing common ocular diseases such as glaucoma, macular degeneration and diabetic retinopathy.

Ant parallel execution – Error with emma code coverage

In our project we tried to run ant tasks in parallel. We were parallelizing emma code coverage task with some other independent build tasks.
At that time we were getting this error:

../project/build.xml:157: java.lang.ExceptionInInitializerError
at org.apache.tools.ant.dispatch.DispatchUtils.execute(DispatchUtils.java:116)
at org.apache.tools.ant.Task.perform(Task.java:348)
at org.apache.tools.ant.Target.execute(Target.java:357)
at org.apache.tools.ant.Target.performTasks(Target.java:385)
at org.apache.tools.ant.Project.executeSortedTargets(Project.java:1337)
...
at org.apache.tools.ant.launch.Launcher.run(Launcher.java:257)
at org.apache.tools.ant.launch.Launcher.main(Launcher.java:104)
Caused by: java.lang.ExceptionInInitializerError
at com.vladium.emma.Processor.run(Processor.java:40)
at com.vladium.emma.instr.instrTask.execute(instrTask.java:77)
at com.vladium.emma.emmaTask.execute(emmaTask.java:57)
...
at org.apache.tools.ant.dispatch.DispatchUtils.execute(DispatchUtils.java:106)
... 31 more
Caused by: java.lang.IllegalArgumentException: null or corrupt input: out
at com.vladium.logging.Logger.create(Logger.java:74)
at com.vladium.logging.Logger.(Logger.java:604)
... 39 more

On analysing this we found a open defect in emma which is linked here:
http://sourceforge.net/tracker/index.php?func=detail&aid=1641403&group_id=108932&atid=651897

Then on further debugging it, I found that the code in some of the logging portion in ant is obtaining locks and releasing it. Then we found out that the defect is in ant. We were running ant 1.7.1 at that time. I upgraded the ant to 1.8.1 and it solved the problem.

In ant 1.8.1, the locks which were obtained and released in logging was removed and an advanced lockless way of logging was introduced.

I hope this is useful for others debugging this issue.

Grails controller integration testing

I wanted to test a groovy controller using a unit test. We had a render whose arguments needs to be verified. Initially we added a test case which extends ControllerUnitTestCase and tried a lot using the renderArgs that is given by the Unit test case. We were able to find that the redirectArgs were working properly but the renderArgs was returning null.

After a bit of struggle, we found that the render arguments are only available in a spring modelandview class which gets constructed when u call render.

Finally, when we changed to the following code

controller.modelAndView.viewName
controller.modelAndView.model

everything started to work.

Even though it is documented in the grails doc in a completely different section in grails doc. The section on testing seems to be misleading.

Mockito mock child classes too…

Recently, I had a requirement to mock out the child classes of a parent mocked class. Typically we reach this kind of situation when we want to mock out a view and its components.

I was able to get a small snipper for solving this problem:

   protected T createMock(Class clazz) {  
     return (T) mock(clazz, createAnswer());  
   }  
   Answer createAnswer() {  
     return new Answer() {  
       public HashMap methodObjectHashMap = new HashMap();  
       @Override  
       public Object answer(InvocationOnMock invocationOnMock) throws Throwable {  
         Method method = invocationOnMock.getMethod();  
         if (method.getReturnType().getName().equalsIgnoreCase(“void”)){  
           return null;  
         }  
         if (methodObjectHashMap.get(method) == null) {  
           methodObjectHashMap.put(method, mock(method.getReturnType()));  
         }  
         return methodObjectHashMap.get(method);  
       }  
     };  
   }  

Instead of using the mockito’s mock method to create a mock object of a class, We can use the creatMock method which will get the required mock object with each properties also as mocked objects.

Devcamp chennai

தோன்றின் புகழொடு தோன்றுக அஃதிலார்
தோன்றலின் தோன்றாமை நன்று.

sums up the first devcamp chennai event. For the benefit of all the people, I am translating the above tirukkural.

Be born with fame without that it is better not be born.

Devcamp’s entry into chennai was well recieved with energy and passion representing the true spirit of developers in chennai. The days preceding to the event as well as the day of event was full of excitement.

I will try to capture some of them ….

300+ registrations in the devcamp wiki

45+ volunteers for the event

3 sponsors for the event – Thoughtworks, ZOHO and Orangescape

180 + people present on the day of event

Community represented by people as diverse as 12th standard students, young entrepreneurs, technology evangelists, Industry leaders in technology and hard core dirty-hand devs.

Flavour of chennai’s very own filter coffee in T-shirt

Paper wiki voting

Ideas floated around open source hardware toincubating technologies.

How to make the old wine tastier (discussions on improving existing tech, code…)

Fishbowl and adhoc sessions added a new taste to it and was loved by devcampers.

Paper bags to be a small part of environment friendliness.

Others can be captured and relived in the twitter world. Search for #dcc1 or Devcamp chennai.

A question left to be answered… When will we meet again in a unconference like this….