Filtering Development Logs in Real Time

Problem

During the course of development, a lot of information is written to the Rails logs. You may be "watching" the development log with the tail -f command, but it's still a challenge to see a specific message go by with all of the other information being logged to that file. You want a way to display a specific type of logging output.

Solution

Filter the output of tail -f with grep, so that you display only the messages that begin with a specific string.

Suppose you are writing a message to the logs from the list action of the Students controller. The log message prints the number of students returned by the call to Student.find :all. In the call to logger in your controller, make sure these messages begin with a unique string that you can easily search for, such as: 

def list
 @students = Student.find :all
 logger.warn "### number of students: #{@students.length}"
end

Now issue the following command in a terminal, from the root of your application, to show only messages beginning with ###: 

$ tail -f log/development.log | grep "^###"

Discussion

tail is a GNU tool that, when passed the -f option, displays a continually updated version of a file, even as lines are being appended to the end of that file. grep is another GNU tool that searches its input for lines matching a specified pattern.

The solution uses the common Unix technique of chaining specialized commands together with the pipe character (|). What this does is tell the system to take the output of the first command (tail -f) and continually feed it as the input of the second command (grep).

Normally, hitting the list action with your browser produces something like this: 

Processing StudentsController#list (for 127.0.0.1 at 2006-06-15 14:57:48) [GET]
 Session ID: e729a7b79df53c2a7e9848fb500fd948
 Parameters: {"action"=>"list", "controller"=>"students"}
 Student Load (0.001656) SELECT * FROM students 
### number of students: 3
Rendering within layouts/students Rendering students/list
 Student Columns (0.008088) SHOW FIELDS FROM students Completed in 0.15091 (6 reqs/sec) | Rendering: 0.01892 (12%) | DB: 0.01443 (9%) | 
200 OK [http://localhost/students/list]

You can see that the message containing the number of students is buried among information about the request and the SQL involved in preparing the response. To make matters worse, if anyone else hits the page you're working, you'll be chasing the output as it flies up your terminal window and out of sight.

Prepending a unique string to your log messages and filtering by that string makes the development log much more useful during a focused debugging session.

On some platforms, you may notice that your log output seems to get swallowed by grep and never makes it to the screen. The problem may be that your version of grep is buffering its output. Your messages will eventually be displayed but not until grep receives enough input from tail. You can turn off buffering with --line-buffering option, which will make sure you receive each line of output in real time.

If you're developing on Windows and don't have access to the tail or grep commands, you should strongly consider installing Cygwin. Cygwin is an open source project that makes many GNU tools (like tail and grep), available in a Windows environment.

See Also