Jake Worth

• debugging

A stumbling block for many people when debugging is reading the stack trace. Today I’d like to discuss this skill.

What is a stack trace? According to Wikipedia: “In computing, a stack trace… is a report of the active stack frames at a certain point in time during the execution of a program.” It’s the answer to the question: “when this system is being observed, what is happening?” Reading stack traces is a core programming skill.

I compare reading stack traces to troubleshooting a component of a car. Imagine that you can’t open your car’s automatic window. Should you dismantle the door and replace the motor that lowers it? That might work, but no, you should not. There are multiple explanations for this problem and the motor is just one. Permit me a few non-mechanic explanations:

• The electrical power to the car might be off
• The window might be stuck or obstructed
• The window control might be broken or missing
• The electrical line that powers the motor might be faulty
• (And finally) the motor might be broken

Your mechanic uses a checklist like this, perhaps just mentally, to ensure the action being taken is the right one.

Debugging works the same way. Isolating the issue to the frontend, backend, data layer, infrastructure, or even your computer, is the only way to ensure you’re fixing the right problem.

Example

Let’s look at a real stack trace! This is Ruby code. Ruby is famous for its readability, so if you aren’t a Rubyist, please try to follow along anyway. Some Rubyists some might consider this example too simple, but I’ve seen a stacktrace like mystify people dozens of times.

For context, this printed in my Chrome Network Tab after an endpoint returned 500.

NoMethodError at /api/delivery_estimates
================================================

undefined method 'each' for nil:NilClass

app/views/platform/api/delivery_estimates/index.v1.jbuilder, line 20
-------------------------------------------------------------------------

   15     end
   16   end
   17   
   18   json.postal_code postal_code
   19   
>  20   json.estimates @estimators.each do |estimator|
   21     json.name estimator.service_name
   22     json.get_it_by estimator.estimate.earliest_promised_delivery_on
   23     json.get_it_by_latest estimator.estimate.latest_promised_delivery_on
   24     json.schedule estimator.evaluated_schedule
   25   

App backtrace
-------------

- app/views/platform/api/delivery_estimates/index.v1.jbuilder:20:in `_354605b230fb799e61b9ae5b2d0a1b7d'
- lib/logbook/rails_ext/action_controller/metal/instrumentation.rb:22:in `block in process_action'
- lib/logbook/rails_ext/action_controller/metal/instrumentation.rb:21:in `process_action'
- app/middleware/ensure_session_id.rb:17:in `call'
- lib/pinterest_catalog_proxy.rb:17:in `perform_request'
- lib/sitemap_proxy.rb:22:in `perform_request'
- lib/logbook/rails_ext/rack/logger.rb:12:in `call_app'

Full backtrace
--------------

- app/views/platform/api/delivery_estimates/index.v1.jbuilder:20:in `_354605b230fb799e61b9ae5b2d0a1b7d'
- actionview (4.2.11.3) lib/action_view/template.rb:145:in `block in render'
- activesupport (4.2.11.3) lib/active_support/notifications.rb:166:in `instrument'
- actionview (4.2.11.3) lib/action_view/template.rb:337:in `instrument'
- actionview (4.2.11.3) lib/action_view/template.rb:143:in `render'
- deface (1.0.2) lib/deface/action_view_extensions.rb:41:in `render'
- actionview (4.2.11.3) lib/action_view/renderer/template_renderer.rb:54:in `block (2 levels) in render_template'
- actionview (4.2.11.3) lib/action_view/renderer/abstract_renderer.rb:39:in `block in instrument'
- activesupport (4.2.11.3) lib/active_support/notifications.rb:164:in `block in instrument'
- activesupport (4.2.11.3) lib/active_support/notifications/instrumenter.rb:20:in `instrument'
...lots of extra lines omitted 😅

Where to start? Look at the first word of the trace:

NoMethodError

This is a common Ruby error that means you tried to call a method that does not exist on an object. Important!

Next:

undefined method 'each' for nil:NilClass

Quite communicative! Something in the code is nil and we tried to call .each on it. Can Ruby iterate over nil? No, it can’t.

Next, we get an actual line of code:

app/views/platform/api/delivery_estimates/index.v1.jbuilder, line 20

Jump to that line quickly. Here it is:

json.estimates @estimators.each do |estimator|

Remember, we were trying to call .each on nil. There’s only one .each here which narrows it down. And what is it being called on? @estimators. This code doesn’t consider that @estimators can be nil, but it can.

We now have one job: find out where @estimators is being set and understand how it can be nil. That is the bug. We’re done debugging and now solving the problem.

Takeaways

After you acquire this knowledge, a neat trick is to stop and verbalize what’s happening. For this example, I’d say:

“When we ask for estimates, our view tries to iterate over a collection of estimators. That collection can be nil, which the API can’t handle.”

An imperfect summary, perhaps, but it’s a lot better than “the magic computer is doing magic things.”

Most of the stack trace is noise. Potentially relevant and interesting noise, but noise nonetheless. Follow your gut. If you’re reading lib/active_support/notifications/instrumenter.rb:20, the last line I shared of the full stack trace, you’re probably off track. Your code is likely causing the issue because it’s almost always your fault.

Happy debugging.

What are your thoughts on this? Let me know!