Wrappers on Debug Print Statements

[justin]

I’m rarely using a debugger as I’ve found that it’s much faster to track down an issue with the right print statements. Basically I can type a lot faster than I can hit the next button and set breakpoints, and wait for the debugger to do its thing.

This is how I set up the wrappers for the print statements. Putting a wrapper on your debug print statements accomplishes 2 things:

1. It’s way easier to see your debug messages in the console log.
2. It’s way easier to grep the code to find the debug messages to remove them before committing your code.

Sometimes, rather than studying the documentation for a problem that I’m having with a Gem, I will put in debug print statements in the Gem’s code. This has helped me many times with the usage of various Ruby Gems and even the Rails source code.

With JavaScript code, it’s not as essential to put in the debug wrappers for separating out your debug statements, as there is not as much logging as the Rails logs. However, having the wrappers sure makes it easier to find the debug statements before committing your code.

The RubyMine Live Templates do a great job of making it super easy to create such debug print wrappers. I use them both for Ruby and JavaScript.

Ruby

puts “ZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZ”
puts “$END$”
puts “ZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZ”

JavaScript

console.log("ZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZ");
console.log("$END$");
console.log("ZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZ");

[justin]

It’s key to also remember these two key tricks:

Ruby

Rather than

puts "User is #{user}"

Use the awesome_print gem

puts "User is #{user.ai}"

That prints the fields of the user in a nice manner. I almost always add the .ai when debug printing objects in Ruby. Huge difference, especially for hashes, arrays, etc.

JavaScript

Rather than

console.log("Some object is " + someObject);

Do

console.log("Some object is %O", someObject);

I always print JavaScript objects using %O. This way you can browse the object properties in the chrome debugger. Huge difference.

[justin]

Here’s a few updates.

JavaScript Print Object

console.log("$END$ %O", );

Ruby Method Info Print

I wanted to print out the method name and parameters with one shortcut: This is how it looks. I bound this to “mmm” for a live template.

puts "ZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZ"
params = method(__method__).parameters.map(&:last)
opts = params.map { |p| [p, eval(p.to_s)] }.to_h
puts "CALLED #{__method__} with params: #{opts.inspect}"
puts "ZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZ"

[andyl]

Hi Justin !!

Here are some methods that I use for Debug Logging:

https://gist.github.com/andyl/84b0a6d9842ba7147e6c

Sometimes a blizzard of debug messages makes it difficult to scan the logs. Some helpful techniques:

1. colorize the log statements, for better readability
2. use unique ‘divider characters’ (like your ‘ZZZZ’) for different debug messages
3. use introspection to output the calling class/method/line number
4. standard debug method (*_log) for fast search & destroy during clean-up time

[justin]

@andyl

1. Cool tip on the colorize log ones. Requires a gem of either rainbow or colorize (warning, colorize conflicts with RuboCop!)
2. I have different rubymine shortcuts for the letters used in the fencing, such as shortcuts for xxx, yyy, aaa, etc. that generate XXXXXXXX, YYYYYYYYYY, etc.
3. Scroll up to see my shortcut for introspecting on the method names and params. I’m digging that one!
4. I don’t need to add the log messages for fast search and destroy when using the fencing, but that’s a nice tip! and it encapsulates the colorize as well. One very real issue is that I work on lots of projects, so not needing to add monkey patches is a bonus. I.e., if the debug statement includes what’s needed.

@andyl, per your gist, are you using a gem for colorization?

[andyl]

I’m using the gem ‘colored’. Haven’t experienced conflicts with it yet.

I saw your rubymine shortcuts - yeah. Maybe something like “puts ‘X’*60” would be a little easier to customize/tweak?

Introspection is a big win. You use a different technique than I used - looks like there are a few ways to do it.

Monkey patching Kernel - maybe not for everyone, but I’ve had good luck with it. If you work on multi-projects, might be handy to wrap your code in a gem.

[justin]

@andyl It’s super easy to see a FENCE of XXXXXXXXXXXXXXXXXXXXXXXXX around statements that need removing before you commit.

[andyl]

I can see how that could be useful.

[justin]

I updated my method print helper to use awesome print. This one’s for @dylangrafmyre:

    puts "ZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZ"
    method_params = method(__method__).parameters.map(&:last)
    method_opts = method_params.map { |p| [p, eval(p.to_s)] }.to_h
    puts "CALLED #{__method__} with params: #{method_opts.ai}"
    puts "ZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZ"

[geoffevason]

You can actually use the same variable multiple times in the same live template. Type once and it appears in each place at the same time. This lets me both label and output a var but only requires typing it once. (I find this helpful when I’m deep into shaving a yak and I’ve got lots of these blocks. )

Template:

puts "ZZZZZZZZZZZZZZZZ"
puts "$OUTPUT$: #{$OUTPUT$.ai}"
puts "ZZZZZZZZZZZZZZZZ"

Output:

ZZZZZZZZZZZZZZZZ
my_hash: { good: 'stuff' }
ZZZZZZZZZZZZZZZZ

[justin]

Hi @geoffevason, I don’t do it the way you showed here because it’s likely that my_hash is declared above and so I can hit the keystroke to autocomplete after maybe the first 3 characters.

On my keyboard, I’d hit:

m y _ opt-/

[justin]

I updated my super useful ZZZ template for RubyMine ruby code.

Now it:

1. prints out location in file
2. evaluates a variable

puts "ZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZ"
puts "$file$: $line$$END$"
puts "$var$ = #{$var$.ai}"
puts "ZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZ"

And this is what it looks like:

[justin]

And another slight improvement to the template. I now print out the method name and I put the cursor after the variable prints.

Note, if you’re not using awesome_print, then change the .ai to .inspect.

puts "ZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZ"
puts "$file$: $line$,  method: #{__method__}"
puts "$var$ = #{$var$.ai}"$END$
puts "ZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZ"

[justin]

Slight improvement. Use the Ruby LINE variable, so when you move statements around, the line number is correct!

puts "ZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZ"
puts "$file$: #{__LINE__},  method: #{__method__}"
puts "$var$ = #{$var$.ai}"$END$
puts "ZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZ"

[justin]

If you’re using atom, here’s how you create a snippet:

http://flight-manual.atom.io/using-atom/sections/snippets/

[justin]

This is great for JS code for logging inside of React Components

  (() => { console.log('$END$: ', props) })() ||