Visualization of rails logs
May 18, 2016
Visualization Ruby Rails Logs Graphviz

At pamediakopes.gr we have many applications built with Rails, each one generating a huge amount of logs. These logs are mostly used for monitoring/alerting and of course debugging. However, your application’s logs have the potential to help you get more insights on your applications and how they interact with other systems, without necessarily using sophisticated 3rd party applications. The challenging part is extracting valuable information and doing it fast! In an attempt to try to get more insights of what is happening during a request, we started experimenting with the idea of using specific information from our Rails logs in order to visualize service dependencies, template rendering and more.

All rails applications have a specific format in which the server logs are written. For each action you have a log of the following format:

Started GET "/example/action_name" for 127.0.0.1 at 2016-04-07 01:46:46 +0200
Processing by ExampleController#action_name as HTML
 Rendered example/action_name.html.erb within layouts/application (0.3ms)
Completed 200 OK in 3ms (Views: 3.0ms | ActiveRecord: 0.0ms)

Also, if you are consuming some external service, for retrieving or sending data, and you are using the httplog gem, the rails log output will look more like the following:

Started GET "/example/action_name" for 127.0.0.1 at 2016-04-07 01:46:46 +0200
Processing by ExampleController#action_name as HTML
Rendered example/action_name.html.erb within layouts/application (0.3ms)
[httplog] Sending: GET http://service-full-url/action
[httplog] Status: 200
[httplog] Benchmark: 0.110814512 seconds
Rendered example/action_name.html.erb within layouts/application (0.3ms)
Completed 200 OK in 3ms (Views: 3.0ms | ActiveRecord: 0.0ms)

The httplog gem logs the requests performed in the backend along with the response status codes and the time required for the requests to complete.

Here is another example of a Rails log, combining many calls to external services and partial rendering:

Started GET "/example/action_name" for 127.0.0.1 at 2016-04-07 01:46:46 +0200
Processing by ExampleController#action_name as HTML
Rendered example/_sub_action_name1.html.erb (0.1ms)
Rendered example/_sub_action_name2.html.erb (0.1ms)
Rendered example/_sub_action_name3.html.erb (0.1ms)
Rendered example/_sub_action_name4.html.erb (0.1ms)
Rendered example/action_name.html.erb within layouts/application (0.4ms)
[httplog] Sending: GET http://service-full-url/action
[httplog] Status: 200
[httplog] Benchmark: 0.110814512 seconds
[httplog] Sending: GET http://service-full-url/action1
[httplog] Status: 200
[httplog] Benchmark: 0.120814512 seconds
[httplog] Sending: GET http://service-full-url/action2
[httplog] Status: 200
[httplog] Benchmark: 0.120814512 seconds
[httplog] Sending: GET http://service-full-url/action3
[httplog] Status: 200
[httplog] Benchmark: 0.120814512 seconds
Completed 200 OK in 23ms (Views: 3.0ms | ActiveRecord: 0.0ms)

Based on the above, a simple idea came to mind:

  1. Read a set of logs.
  2. Get the useful information from it.
  3. Present it in a tree.

The simplest thing to do, given that the logs tend to be pretty much of the same format, is to use regular expressions to try to match any useful information that we want to visualize. At this point, we consider you are familiar with regular expressions (regex).

In the following examples we will try to cover the following items:

  1. Create a tree originating from a single node that would describe the action (path requested, controller processing the request etc)
  2. Note all partials rendered, while grouping the same ones. If, for example, we were to be rendering the same partial within a loop but with different locals, we wanted to print it as a single node but note the number of times it was rendered.
  3. Note all service calls made, while grouping the same ones. If, for example, we were to be making the same requests over and over again in the same action (especially if you were not to cache the response), we wanted to print it as a single node but keep a note of all the numbers requested.

To create our tree we decided to go with Graphviz library by using the related ruby gem. It is not that dynamic but it provides just the simplicity we want for a prototype. To create a tree you just have to:

  1. initialize the tree.
  2. add nodes and edges between them (as you see fit).
  3. output the tree to an image file.
  4. do whatever you want with it.

Some useful info to keep in mind on creating trees with Graphviz ruby client:

  • The tree is created by default from top to bottom, making each sub-tree being placed next to each other and all leaf nodes to follow underneath them. This, in our case at least, didn’t really help, as it made all trees incredibly large to view. We changed it to “LR” which is actually left-to-right making all trees fall one below the other and all leaf nodes follow right next to them.
  • All nodes and edges can be customized to the shape and style you want. For more info you can review the examples provided in the Graphviz repository and especially this guide on the attributes of nodes and edges.
  • Each node understands the name given as a key, making all node creations with the same name fall into the same node. For example, if we were to create a node with label “action 1” and for some reason another node with the same label, a single node would appear.

The following code combines some regex wisdom and the capabilities of Graphviz in order to convert a Rails log into a tree which is then rendered as a png image.

 1 def rails_log_visualization(log)
 2   data = { :nodes => [] }
 3 
 4   # Initialize a GraphViz tree
 5   g = GraphViz::new( :G, :type => :digraph)
 6 
 7   # Set the direction of the tree to left-to-right rather than the default (top-to-bottom)
 8   g[:rankdir] = 'LR'
 9 
10   # Split the initial log into one section per action
11   log.split('Started ').each do |action|
12   if action.present?
13     # Read the action of the section
14     action_parsed = /(?<action>.*) for/.match(action)[:action]
15 
16     # Read the controller who processed the action
17     controller_processing_request = /Processing by (?<controller>.*) as/.match(action)[:controller]
18 
19     # Read all lines of this section one by one
20     action.split("\r\n").each do |log_line|
21       rendered_partials = []
22       service_requests = []
23 
24       # Check if line includes the description of a rendered partial
25       partial_in_line = /Rendered (?<partial>(\S)*)/.match(log_line)
26 
27       # Check if line includes the description of a service request
28       service_request_in_line = /\[httplog\] Sending: (?<service>.*)/.match(log_line)
29 
30       # If partial has been found, pass it down the list
31       if partial_in_line.present?
32         rendered_partials << partial_in_line[:partial]
33       end
34 
35       # If service has been found, pass it down the list
36       if service_request_in_line.present?
37         service_requests << service_request_in_line[:service]
38       end
39     end
40   end
41 
42     # Build a hash of all the nodes to be included
43     data[:nodes] << {
44       :label => action_parsed,
45       :controller => controller_processing_request,
46       :rendered_partials => rendered_partials.group_by { |x| x }, # group all partials found based on the partial name
47       :service_requests => service_requests.group_by { |x| x } # group all services found based on the service name
48     }
49   end
50 
51   data[:nodes].each do |node|
52     graph_node = g.add_nodes(node[:label], :label => "<<b>#{node[:label]}</b><br/><i>#{node[:controller]}</i>>")
53 
54     node[:rendered_partials].each do |partial, partials_array|
55       partial_node = g.add_nodes(partial, :shape => :component)
56       g.add_edges(graph_node, partial_node, :label => "<<i>Renders<br/>(#{partials_array.size} times)</i>>")
57     end
58 
59     node[:service_requests].each do |service, services_array|
60       service_node = g.add_nodes(service, :shape => :note)
61       g.add_edges(graph_node, service_node, :label => "<<i>Includes requests to<br/>(#{services_array.size} times)</i>>")
62     end
63   end
64 
65   g.output(:png => "graph.png" )
66 end

Through this and using the above examples we could produce the following trees:

Tree 1 Tree 1 - Simple scenario

Tree 2 Tree 2 - Scenario with service requests

Tree 3 Tree 3 - Multiple partials and service calls

Obviously the above ones are simple scenarios, but by extending the code a bit more, one could easily:

  • Parse all database interactions (select, insert, update) per table.
  • Parse all assets being compiled in each action.
  • Group the services per host and then split those per action.
  • Record processing time per resource.
  • Style the nodes/edges according to processing time.
  • Define flows between actions for better tracking.
  • Find a more dynamic tool for visualization.
  • Expand this functionality to logs from other technologies.
  • And pretty much.. Whatever you might want!

Now, get your axe up and like a good lumberjack that you are, cut down those ugly logs into valuable information.

Update

The above functionality has been extracted to a new gem called logs_visualizer. Feel free to use it and, even better, help us extend it!

Share on