ruby

Squash Your Ruby and Rails Bugs Faster

Martin Streicher

Martin Streicher on

Squash Your Ruby and Rails Bugs Faster

A bug in software can be disruptive, elusive, maddening, and invasive. Indeed, a developer often needs the tenacity of Edison to find and fix an issue.

But grit isn't the only asset a developer requires. One also needs information to debug code: What are the symptoms and effects of the issue? What is its frequency? Pervasiveness? Provenance? The evidence and artifacts of a bug — a core dump, stack trace, log, or test case — are invaluable.

Let's explore a few techniques and tools readily available to Ruby and Rails developers for gathering and investigating evidence of an issue. Data can't supplant tenacity, but it can help to ease your efforts (and spare you your sleep).

Use Environment Variables to Tune Your Tools in Rails

Rails provides some excellent tools to peer into a running application, including a configurable Logger to capture diagnostics of its own and any that you'd like to add. Rails also provides a verbose query log to pinpoint the origin of database queries and a verbose enqueue log to illuminate where background jobs are queued. The latter two logs are enabled by default in the development environment; you can enable both in other environments with two statements.

Ruby
## # In any initializer... enable the verbose query log to see the file # name and line number of the code initiating each query ActiveRecord.verbose_query_logs = true ## # In config/application.rb or any environment initializer, enable the # queueing log to find where each job is enqueued config.active_job.verbose_enqueue_logs = true

A lesser-known log option available since Rails 7 annotates each SQL query with comments. If you add the following to config/application.rb or any environment file:

Ruby
## # Add to config/application.rb or any environment initializer file config.active_record.query_log_tags_enabled = true

Your query log is automatically amended with the application name, controller name, action name, or background job name. The following sample output comes directly from Rails's debugging guide:

text
Article Load (0.2ms) SELECT "articles".* FROM "articles" /*application='Blog',controller='articles',action='index'*/ Article Update (0.3ms) UPDATE "articles" SET "title" = ?, "updated_at" = ? WHERE "posts"."id" = ? /*application='Blog',job='ImproveTitleJob'*/ [["title", "Improved Rails debugging guide"], ["updated_at", "2022-10-16 20:25:40.091371"], ["id", 1]]

You likely do not want to enable all these features in production. Log generation can be costly in terms of memory and time (finite resources for an application under load).

However, there are exceptions. You may want to briefly enable an on-demand feature, especially when debugging in development and test modes. Rather than alter code (and perhaps redeploy) to enable or disable a diagnostic, use environment variables to control state. In some environments, such as Heroku, changing the setting of an environment variable does not mandate a new deployment.

For example, you can define a set of variables to control logging and verbosity.

Variable NamePurposeValues
COMMENTED_QUERY_LOGEnable comments in query logNon-blank value enables feature
LOG_ALLEnable all logging featuresNon-blank value enables feature
LOG_LEVELControl the threshold for log messagesdebug, info, warn, error, fatal, unknown (from most verbose to least verbose order)
VERBOSE_ENQUEUE_LOGDisplay where jobs are queuedNon-blank value enables feature
VERBOSE_QUERY_LOGShow the origin of each Active Record queryNon-blank value enables feature

For convenience, create a small class to query configuration settings.

Ruby
## # Put this in a file such as config/initializers/env_configuration.rb class EnvironmentConfiguration def self.enabled?(envvar) Rails.env.development? || ENV.fetch('LOG_ALL', nil).present? || ENV.fetch(envvar.to_s, nil).present? end end

Now use the variables and the code to set logging features in config/application.rb:

Ruby
## # Centralize configuration of all logging features in config/application.rb # module MyApplication class Application < Rails::Application # . . . ActiveRecord.verbose_query_logs = EnvironmentConfiguration.enabled?('VERBOSE_QUERY_LOG') config.active_job.verbose_enqueue_logs = EnvironmentConfiguration.enabled?('VERBOSE_ENQUEUE_LOG') config.active_record.query_log_tags_enabled = EnvironmentConfiguration.enabled?('COMMENTED_QUERY_LOG') config.log_level = (ENV.fetch('LOG_LEVEL', nil).presence || 'info').to_sym end end

Use your shell, a dotenv file, your continuous integration, or hosting and deployment platform to set each option. You can also use a feature on demand. Simply start the application with the environment variable defined on the command line.

Shell
LOG_ALL=on LOG_LEVEL=debug bundle exec rails s

Tune Puma for Development

Building on the previous section, let's look at how to use environment variables to tailor your Puma configuration for debugging in the development environment.

Typically, Puma is configured to maximize throughput in production, running multiple workers and many threads per worker. In development, you want the opposite: one worker, one thread, and a very long timeout to allow for interactive debugging. Each of those is a parameter you can tune.

Alter config/puma.rb to reflect the following code.

Ruby
## # Control thread count with environment variables. # Each environment setting, if set, is always a string. Use `Integer` to # convert the string to an integer value. # max_threads_count = Integer ENV.fetch('PUMA_MAX_THREADS', 5) min_threads_count = Integer ENV.fetch('PUMA_MIN_THREADS, max_threads_count) threads min_threads_count, max_threads_count ## # Specify the duration Puma waits before terminating a worker. # The default is 30 seconds. # worker_timeout Integer ENV.fetch('PUMA_WORKER_TIMEOUT', 30) ## # Set the number of workers worker_count = Integer ENV.fetch('PUMA_WEB_CONCURRENCY, 2) workers worker_count preload_app! if worker_count.positive?

You can now configure the three environment variables to control Puma in each environment. In development, set the values to optimize for interactive debugging.

Shell
export PUMA_MAX_THREADS=1 export PUMA_WORKERS=0 export PUMA_WEB_CONCURRENCY=0 export PUMA_WORKER_TIMEOUT=3600

If you want to validate your Puma settings, set the environment variable PUMA_LOG_CONFIG=true and start your application. Puma emits its active configuration on startup.

Shell
=> Booting Puma => Rails 6.1.7.7 application starting in development => Run `bin/rails server --help` for more startup options Configuration: . . . - environment: development - max_threads: 5 - min_threads: 5 - worker_timeout: 3600 - workers: 0

Coincidentally, the default Puma configuration in the most recent Rails release is similar to what's shown here (thanks to Nate Matykiewicz for the tip).

Run Background Jobs Inline

A Rails application of any complexity typically leverages background jobs to run compute-intensive and (relatively) long-running tasks. Background jobs run asynchronously, disconnected from the request/response cycle. Ideal candidates for "out of band" processing include generating reports, sending emails, and interacting with third-party APIs. But the asynchronous nature of jobs also complicates debugging.

To simplify troubleshooting, run jobs immediately in your local development and test environments. In immediate mode, jobs are not queued, but instead execute instantaneously. Running in the "foreground", you can set breakpoints and inspect state interactively.

Let's look at an example using Delayed Job, a popular and easy-to-manage queueing backend for Active Job. Delayed Job provides a setting to enable queueing. By default, the setting is true and jobs are queued as per usual. However, if set to false, jobs run immediately.

Add the following code to your application in config/initializers/delayed_job.rb:

Ruby
Delayed::Worker.delay_jobs = ENV.fetch('DELAYED_JOBS_DISABLE_JOB_QUEUES', false).blank?

If DELAYED_JOBS_DISABLE_JOB_QUEUES is set to any value, queueing is disabled. If the environment variable is blank or not defined, queueing is enabled.

Next, in your shell, on the command line, or in your dot files, set DELAYED_JOBS_DISABLE_JOB_QUEUES as needed.

Shell
# Set the variable in the current shell export DELAYED_JOBS_DISABLE_JOB_QUEUES=true
Shell
# Set the variable only for the current command DELAYED_JOBS_DISABLE_JOB_QUEUES=true rails s
Shell
# In .env.development, .env.local, and/or .env.test, add the line... DELAYED_JOBS_DISABLE_JOB_QUEUES=true

Set the environment variable to nothing or delete the environment variable to restore queueing.

Shell
# Set the variable to blank export DELAYED_JOBS_DISABLE_JOB_QUEUES= # Remove the variable from the environment unset DELAYED_JOBS_DISABLE_JOB_QUEUES

There are no rules for naming environment variables. Choose names meaningful to you. One helpful convention to categorize variables is to add a package name as a prefix, such as PUMA_ and DELAYED_JOB_. The former indicates variables affecting Puma; the latter connotes variables used by Delayed Job.

Peer Into Network Calls

Like background jobs, Rails applications can also consume application programming interfaces (APIs). APIs provide access to external services, such as GraphQL databases, e-commerce transactions, and public data sources.

Here's another example to conditionally emit HTTP requests and responses from the Net::HTTP library. If the environment variable DEBUG_HTTP is set to any non-blank value, the outgoing request and inbound responses are printed to STDOUT.

Ruby
def construct_uri(hostname:, path:, port:, params: {}, protocol: 'https') target = Addressable::URI.new.tap do |uri| uri.hostname = hostname uri.path = path uri.port = port uri.query_values = params uri.scheme = protocol end URI.parse target end def debug? ENV.fetch['DEBUG_HTTP'].present? end def request uri = construct_uri(...) Net::HTTP.new(uri.host, uri.port).tap do |http| http.set_debug_output($stdout) if debug? http.use_ssl = uri.scheme == "https" end end

To see the network activity, simply start the application with the environment variable defined on the command line.

Shell
DEBUG_HTTP=on bundle exec rails s

The debug? method provides some abstraction from the actual flag implementation. It, and the rest of this code, can form a base class for all your network requests, as shown in this gist taken from production code.

Add Ruby Gems to Your Toolbox

The universe of Ruby gems is vast: it's impossible to cover all the great gems available for debugging. Instead, let's look at a few tools you can add today for an instant boost. You'll likely add each of these to all your projects.

  • awesome_print and table_print create rich, readable inspections of Ruby data structures, including Active Record models. You can use either gem in code or from the console.

    Here is an example of a model emitted by awesome_print in the console:

    Ruby
    > ap User.find_by(email: 'george@bigbrother.gov') #<User:0x00000001163482f0> { :account_balance => 0.0, :confirmed_at => Mon, 11 Mar 2024 12:29:30.000000000 EDT -04:00, :created_at => Mon, 11 Mar 2024 12:29:30.000000000 EDT -04:00, :email => "george@bigbrother.gov", :encrypted_password => "992c45d528f9b445de3d6653e14d3e6165171944", :first_name => "George", :last_name => "Orwell", :sign_in_count => 0, :state => "active" }

    Instead of p, use ap to show the enhanced output. awesome_print lists attributes in alphabetical order, one attribute per line, among other niceties.

  • better_errors replaces the standard Rails error page with an enhanced stack backtrace, parameter list, and an interactive console where you can probe the stack frame and variables at the scene of the exception. You can also tie source code links to your favorite editor. Here is code to tie better_errors to Visual Studio Code:

    Ruby
    if Rails.env.development? BetterErrors.editor = if (ENV['BETTER_ERRORS_EDITOR'].presence || ENV['EDITOR']) =~ /vscode/i proc { |file, line| "vscode://file#{file}:#{line}" } else :macvim end end

    Run export BETTER_ERRORS_EDITOR=vscode in your shell and restart the Rails server. Now links to files open automatically in Visual Studio.

  • Keep the faker and factory_bot gems (or their alternatives) in both the testing and development groups in Gemfile. Both are invaluable if you need to generate data quickly in the console.

    Ruby
    group :development, :test do # other gems # ... gem 'factory_bot' gem 'faker' end

One more idea: If you use AppSignal as your application monitoring tool, it has features to interpret your logs and pinpoint the source of errors. See Debugging in Ruby with AppSignal for more details.

Debugging is a Skill

Debugging code is something of an art, and like any creative endeavor, the more practice you have, the better you become.

Debug while pairing with another developer, especially an experienced developer. If your partner is willing, think out loud together and exchange hunches and insights.

Go forth and hack!

P.S. If you'd like to read Ruby Magic posts as soon as they get off the press, subscribe to our Ruby Magic newsletter and never miss a single post!

Martin Streicher

Martin Streicher

Our guest author Martin is a professional Ruby developer. He earned an advanced degree in Computer Science from Purdue University, served as Editor-in-Chief of Linux Magazine (US) for five years, and was the founding author of the "Speaking in Unix" column published in IBM's former developerWorks portal. When not coding or writing about code, he collects art and wrangles many small dogs.

All articles by Martin Streicher

Become our next author!

Find out more

AppSignal monitors your apps

AppSignal provides insights for Ruby, Rails, Elixir, Phoenix, Node.js, Express and many other frameworks and libraries. We are located in beautiful Amsterdam. We love stroopwafels. If you do too, let us know. We might send you some!

Discover AppSignal
AppSignal monitors your apps