Understanding complex Rails projects – Ruby on rails stack trace made easy

The challenge of understanding complex systems

Imagine a scenario where a project is so large and its features so complex that tracking and understanding the entire flow can take days. Working in such a scenario, especially if test coverage is low and the code lacks an organized architecture, can be a significant challenge. To simplify this process and help understand how a feature behaves, the rails_tracepoint_stack gem was created, dissecting the applications stack trace.

How the Rails backtrace can help us

Debugging applications without a tool to facilitate this process can be challenging, and one alternative is to use the debug gem along with the backtrace command. The backtrace command is capable of bringing the logs about executed code directly to the console of the debug gem. Using a scenario close to a real one, let’s use the Forem project, applying the backtrace command from the debug gem on the article creation action:

article = Articles::Creator.call(@user, article_params_json)
debugger

When executing the a request test:

rspec ./spec/requests/articles/articles_create_spec.rb:12

and the execution reaches the debugger method, a console will be opened, and we can execute the backtrace command:


(rdbg) backtrace    # command
=>#0    ArticlesController#create at /app/app/controllers/articles_controller.rb:151
  #1    ActionController::BasicImplicitRender#send_action(method="create", args=[]) at /usr/local/bundle/gems/actionpack-7.0.8.4/lib/action_controller/metal/basic_implicit_render.rb:6
  #2    AbstractController::Base#process_action at /usr/local/bundle/gems/actionpack-7.0.8.4/lib/abstract_controller/base.rb:215
  #3    Datadog::Tracing::Contrib::ActionPack::ActionController::Instrumentation::Metal#process_action(args=["create"]) at /usr/local/bundle/gems/ddtrace-1.16.2/lib/datadog/tracing/contrib/action_pack/action_controller/instrumentation.rb:105
  #4    ActionController::Rendering#process_action at /usr/local/bundle/gems/actionpack-7.0.8.4/lib/action_controller/metal/rendering.rb:165

  < ... >

  #195  [C] Kernel#load at /usr/local/bundle/bin/bundle:25
  #196  <main> at /usr/local/bundle/bin/bundle:25

We can see that, although quite detailed, the output does not provide much insight into how the Articles::Creator class is functioning. Among the large quantity of logs provided, one alternative is to filter using regex. However, it is a challenge to define the ideal pattern to apply. Let’s try filtering the class name using regex:

(rdbg) backtrace /Articles/    # command
=>#0    ArticlesController#create at /app/app/controllers/articles_controller.rb:151

Again, the information returned by the backtrace feature provides few details, not focusing on the class’s internal implementation. In this article, we shall present the rails_tracepoint_stack gem and compare its backtrace to this one.

Automating the code exploration with RailsTracepointStack

This ruby library captures and filters the stack of method calls. By default, it shows only the stack of code created by the developer, along with the parameters passed to the source class or module and its full path. This helps the developer visualize the entire execution flow of the code during feature execution.

This gem has two basic configurations in Rails applications: globally enabling it by setting the RAILS_TRACEPOINT_STACK_ENABLED environment variable to true, which captures and displays the call stack of all code created by the developer until the application finishes; or inline by passing code blocks to the Tracer. Let’s consider a pretty simple scenario, where we have a module with the method, which is used by a class that includes it:

module Foo
    def puts_message(message)
        puts message
    end
end

class Bar
    include Foo

    def initialize(message:)
        @message = message
    end

    def perform
        RailsTracepointStack.enable_trace do
            puts_message(@message)
        end
    end
end

By adding your code inside the block

RailsTracepointStack.enable_trace do
    puts_message(@message)
end

and calling it

 Bar.new(message: "Hello World").perform

The gem will capture the entire call stack and filter by default only the stack related to the code implemented by the developer, ignoring code executed by possible gems or even modules of the language itself, providing a formatted output like:

called: Foo#puts_message in COMPLETE_PATH_TO_YOUR_FILE/app/services/foo:METHOD_LINE with params: {:message=>"Hello World"}

In this straightforward example, it’s easy to follow the code execution flow without using the gem’s assistance. However, in a larger project with numerous modules, callbacks, and conditionals, having an automated return and a well-formatted call stack is highly beneficial.

Let’s use the same scenario, using the Forem project, applying the RailsTracePoint.enable_trace function around the Articles::Creator call :

RailsTracepointStack.enable_trace do
    article = Articles::Creator.call(@user, article_params_json)
end

and let’s run the same request test again to generate info about the article creation:

rspec ./spec/requests/articles/articles_create_spec.rb:12

Examining the logs from the rails_tracepoint_stack.log file reveals a detailed execution of the programmer’s code implementation, providing a detailed execution of what was executed by the class Articles::Creator call, showing services, models, validators, etc called during the execution:

called: Articles::Creator#initialize in /app/app/services/articles/creator.rb:21 with params: {:user=>#<User id: 21, apple_username: nil, articles_count: 0, badge_achievements_count: 0, blocked_by_count: 0, blocking_others_count: 0, checked_code_of_conduct: true, checked_terms_and_conditions: true, comments_count: 0, created_at: "2024-08-01 20:57:59.911703109 -0230", credits_count: 0, email: "person1@example.com", export_requested: false, exported_at: nil, facebook_username: nil, feed_fetched_at: "2017-01-01 01:30:00.000000000 -0330", following_orgs_count: 0, following_tags_count: 0, following_users_count: 0, forem_username: nil, github_repos_updated_at: "2017-01-01 01:30:00.000000000 -0330", github_username: "github1", google_oauth2_created_at: nil, google_oauth2_username: nil, last_article_at: "2017-01-01 01:30:00.000000000 -0330", last_comment_at: "2017-01-01 01:30:00.000000000 -0330", last_followed_at: nil, last_moderation_notification: "2017-01-01 01:30:00.000000000 -0330", last_notification_activity: nil, last_onboarding_page: nil, last_reacted_at: nil, latest_article_updated_at: nil, name: "Margery \"Lester\" \\:/ Hansen", old_old_username: nil, old_username: nil, onboarding_package_requested: false, organization_info_updated_at: nil, payment_pointer: nil, profile_image: "16042b3c-131e-4639-9ce4-88e63620d770.jpeg", profile_updated_at: "2017-01-01 01:30:00.000000000 -0330", rating_votes_count: 0, reactions_count: 0, registered: true, registered_at: "2024-08-01 20:57:59.868828302 -0230", reputation_modifier: 1.0, saw_onboarding: true, score: 0, secret: nil, signup_cta_variant: "navbar_basic", spent_credits_count: 0, stripe_id_code: nil, subscribed_to_user_subscriptions_count: 0, twitter_username: "twitter1", unspent_credits_count: 0, updated_at: "2024-08-01 20:58:00.361210945 -0230", username: "username1">, :article_params=>#<ActionController::Parameters {"title"=>"NEW TITLE 61", "body_markdown"=>"Yo ho ho31", "tag_list"=>"yo", "published_at"=>nil} permitted: true>}
<...>
called: ApplicationRecord#decorate in /app/app/models/application_record.rb:108 with params: {}
<...> 
called: Article#evaluate_markdown in /app/app/models/article.rb:730 with params: {:content_renderer=>nil, :result=>nil, :front_matter=>nil, :e=>nil}
<...>
called: ##call in /app/app/services/markdown_processor/fixer/base.rb:16 with params: {:markdown=>"Yo ho ho65"}
<...>
called: ##processor in /app/app/services/content_renderer.rb:5 with params: {:value=>MarkdownProcessor::Parser}
<...>
called: Taggable#validate_tag_name in /app/app/models/concerns/taggable.rb:50 with params: {:tag_list=>["yo"]}
called: Tag#validate_name in /app/app/models/tag.rb:206 with params: {}
<...>

Using this same stack logs, we have another good example of useful information: the presence of model callbacks, as the ones called after creating an article (also there are other callbacks called before the saving):

 after_save :create_conditional_autovomits
 after_save :bust_cache
 after_save :collection_cleanup
 after_save :generate_social_image

which produced the logs:

<...>
 called: Article#create_conditional_autovomits in /app/app/models/article.rb:1028 with params: {}
 <...>
 called: Article#bust_cache in /app/app/models/article.rb:1006 with params: {:destroying=>false, :cache_bust=>nil}
 <...>
 called: Article#collection_cleanup in /app/app/models/article.rb:669 with params: {:collection=>nil}
 <...>
 called: Article#generate_social_image in /app/app/models/article.rb:1015 with params: {:change=>nil}
 <...>

Among others, these logs provide a detailed look at the code executed during the operation of this feature, including template callbacks (an interesting post by Codeminer42 here), which can sometimes run without the developer noticing.

Customizing RailsTracepointStack for your necessities

rails_tracepoint_stack also provides a configuration interface where you can:

Observe only stack calls from files where the path matches a specific pattern, providing a more targeted view of the code execution:

RailsTracepointStack.configure do |config|
    config.file_path_to_filter_patterns << /services\/foo.rb/
end

Ignore a predefined list of files based on patterns, such as

RailsTracepointStack.configure do |config|
    config.ignore_patterns << /services\/foo.rb/
end

Return the entire stack trace without filtering, including code from gems and the framework itself:

RailsTracepointStack.configure do |config|
    config.log_external_sources = false
end

Why use RailsTracePointStack instead of Debug#backtrace

RailsTracePointStack compiles information in a clear and organized manner while offering advanced filtering options that are easy to use. Compared to the Rails backtrace function, RailsTracePointStack provides:

By default, only shows code created by the developer, excluding code from libraries, modules from Ruby, etc.
Advanced filtering for excluding specific files and folders of the stack tracing;
Intuitive way to configure the tracer to catch traces just from specific folders;
Different trace output formats;
Intuitive way to trace specific blocks of code or even the entire application.

With the rails_tracepoint_stack gem and a few configurations, you should be able to understand how a complex system works, spend less time debugging and more time being assertive and effective with your project. Thank you for following along, and feel free to add rails_tracepoint_stack to your arsenal of gems!