the grep is a lie

grep is a wonderful tool for digging through logs on specific issues, but there are a few cases when people misuse it and claim the logs don’t have the answers when grep didn’t yield an answer.

Here’s an example of Rails application logging from Ruby on Rails Guides:

Processing PostsController#create (for 127.0.0.1 at 2008-09-08 11:52:54) [POST]
  Session ID: BAh7BzoMY3NyZl9pZCIlMDY5MWU1M2I1ZDRjODBlMzkyMWI1OTg2NWQyNzViZjYiCmZsYXNoSUM6J0FjdGl
vbkNvbnRyb2xsZXI6OkZsYXNoOjpGbGFzaEhhc2h7AAY6CkB1c2VkewA=--b18cd92fba90eacf8137e5f6b3b06c4d724596a4
  Parameters: {"commit"=>"Create", "post"=>{"title"=>"Debugging Rails",
 "body"=>"I'm learning how to print in logs!!!", "published"=>"0"},
 "authenticity_token"=>"2059c1286e93402e389127b1153204e0d1e275dd", "action"=>"create", "controller"=>"posts"}
New post: {"updated_at"=>nil, "title"=>"Debugging Rails", "body"=>"I'm learning how to print in logs!!!",
 "published"=>false, "created_at"=>nil}
Post should be valid: true
  Post Create (0.000443)   INSERT INTO "posts" ("updated_at", "title", "body", "published",
 "created_at") VALUES('2008-09-08 14:52:54', 'Debugging Rails',
 'I''m learning how to print in logs!!!', 'f', '2008-09-08 14:52:54')
The post was saved and now the user is going to be redirected...
Redirected to #
Completed in 0.01224 (81 reqs/sec) | DB: 0.00044 (3%) | 302 Found [http://localhost/posts]

Grepping for “learning” will give us just a peek but there’s much more information to be found in the full request.

# grep learning applog.log

 "body"=>"I'm learning how to print in logs!!!", "published"=>"0"},
New post: {"updated_at"=>nil, "title"=>"Debugging Rails", "body"=>"I'm learning how to print in logs!!!",
 'I''m learning how to print in logs!!!', 'f', '2008-09-08 14:52:54')

If you know the exact format of your applications log messages, you can use output context flags within grep ( -A -B and -C). However, a lot of the time the exact number of context lines needed is unknown or a particular stack trace could have a varying length.

Rails applications aren’t the only ones - the logging module within Nova also falls to this same issue. Common Log Format seems to get around the problem, but many modern applications or ones in debug mode have multiline/transaction-ID logging which make sole reliance on grep a bad decision.

My preferred technique: Use grep to determine which log file to open in less. Then, use the pattern search within less that I grepped and take a look at the clues provided in the context. Sometimes it’s as simple as two lines later you’ll see a SIGTERM, but you wouldn’t have grepped for SIGTERM.

Another tip with less and pattern matching: if you have a large file and you know relative to the file, your search string is toward the bottom hit G to move less to the bottom of the file, then do your /pattern search, but then press N to find the previous result.

One last thing: if you haven’t given zless/ zgrep a try on compressed files, they’re worth their weight in gold.