There have been many times when I've been debugging a complicated issue. More often than not, it was something crazy that I had done and it seemed like a good idea at the time. Whether it is a endless recursive loop or just a good ole bug in the code.
We all have our own ways of debugging and sometimes they're really efficient. However, other times, they're just familiar so that is our first weapon of choice. Just because something is familiar does not make it efficient. Sometimes branching out and trying something new may not be efficient due to the initial learning curve.
However, this article will take two most likely familiar techniques and combine them into one simple, rememberable and powerful debugging technique. Some time ago, Aaron Patterson had written an article on Puts Debugging and it was a great read. Depending on our application and the complexity of the bug, this may not be enough.
Within virtually every *nix system (Ubuntu, Centos, MacOS, etc.) there is a command that can show the last bits of a file. From your terminal within the application directory, you can run this command to see the last 100 lines of your file.
tail -100 log/development.log
Pretty cool huh? While you have your application running on a separate terminal, you can use this command to view the logs as they occur.
tail -f log/development.log
This is really powerful to see errors and other issues that may be happening. Any kind of successful request or failure will be logged here since within our `config/environments/development.rb` we have the following set by default.
config.log_level = :debug
If you don't have this in there, it will be
:debug by default.
Grep is another popular command that I use all the time. It makes life so much easier when parsing a file to fine something specific. To keep things simple, I can
grep a the output of a file and it will only show the relevant information.
> cat Gemfile | grep source source 'https://rubygems.org'
So we can call something like
cat Gemfile which would display the entire contents of our Gemfile in the terminal. Combine this with a pipe (|) and
grep with our search term and it returns the relevant results. Really cool!
Tail + Grep
While reading the development logs is fairly straight forward once you are familiar with the output and you know what you're looking for, it is still cumbersome if there is a LOT of information that is getting returned on a single request. Sometimes, it's not as simple as reading the relevant bits since there is a bunch of distracting information in between.
So when I'm debugging an issue, whether it is a silly background job not running properly or some other nuance, I will throw something like this within my code to test.
This gives some separation of the logs and it also gives me a nice little wrapper to try and see what's going on. However, on complicated queries or requests, this may still get buried in the mix of the rest of the logs. Instead, we can simply do something like this within the relevant bit of code.
And within my terminal, I'll tail the logs and grep for
DEBUG with a command like this.
tail -f log/development.log | grep DEBUG
Now, not only am I not bothered by the rest of the logs polluting my terminal, but I can clearly see when this bit of code has ran and also see the output without trying pick through a bunch of logs.