Tracing in Rails

This post is about using TracePoint in Rails 5. It’s a reference for myself, but may be helpful to someone else as a solution. Any suggestions to improve the code are much appreciated.

When working with a large, unfamiliar codebase, and not being up to speed with the business domain, I need all the help I can get when tracking down bugs or making changes. Indeed, the older I get, the more help I need.

One approach I find useful is to increase the amount of data being logged, and at the same time filtering the noise. This is especially important when working with threaded code as a debugger doesn’t scale.

The IDE I use for work currently aggregates log data from several sources including:

  • Console output from the Puma Server (Server/Rails/Source debug messages/output)
  • Standard events from CefSharp event handlers, such as console.log messages
  • A Custom Request Handler in CefSharp to gather request information and post data

As useful as this is, sometimes I wish I could increase the log verbosity in a certain context, when performing a certain action, to understand more; for example when creating a new customer.

It turns out that TracePoint in Ruby is perfect for that. TracePoint is “A class that provides the functionality of Kernel#set_trace_func in a nice Object-Oriented API.”

Sounds great, but you have to be judicious. You can literally bring your application to a grinding halt if you process too many events. Ask only for those events you need, and of those, filter out whichever you don’t need. The filtering aspect should be something very debug/task specific to avoid being flooded with messages.

In my case I wanted to track method entry and exit of my Rails classes, which the :call and :return events allow you to do. But as a pleasant bonus, TracePoint allows you to access the current binding, so you can also grab argument names and values, local variable values, and the return value. That’s a lot of useful information! I also want to enable or disable the tracing as needed.


I’ve settled on a solution that activates tracing per request – if tracing is enabled. Managing multiple processes and instances of TracePoint was quite challenging:


return unless Rails.env.development?

class TracingMiddleware
  def initialize(app)
    @app = app

  def call(env)
    status, headers, response =
    [status, headers, response]

We need append this line to config\environments\development.rb:

config.middleware.use TracingMiddleware


To configure a TracePoint, and expose it to my controller, I created the following tracing.rb file in the config\initializers folder:

return unless Rails.env.development?

module Tracing
  class Settings
    # variables we are not interested in
    Ignore = %[session]

    # Trace is a constant so the controller can access it
    Trace =

    attr_accessor :tracing, :filter

    def initialize
      @tp = nil
      @tracing = false
      @filter = nil

    def start
      return if @tracing.blank?

      unless @tp.nil?

      puts "[#{}] configuring trace"

      if @filter.blank?
        puts "[#{}] using default filter"

        @filter = [

      # we only want the :call and :return events
      @tp = TracePoint.trace(:call, :return) do |tp|

        # source must be a class - off for now
        # next unless tp.self.is_a?(Class)

        # get the source path - includes the method
        path = caller[0]

        # path must include the project app folder
        next unless path.include? 'servicestream'
        next unless path.include? 'app'

        # apply the filter
        next if @filter.any? { |f| path.include? f }

        # output the pid file, line, and event type
        pid =
        puts "[#{pid}] #{path} [#{tp.event}]"

        #examine the call event and grab the arguments
        if tp.event == :call
          args = { |n|
            Ignore.include? n.to_s

          if args.any?
            print "[#{pid}] args:"
            puts { |n|
              [n, tp.binding.eval(n.to_s).inspect]

        # next we examine the return event
        if tp.event == :return

          # and get any local values
          locals = tp.binding.
            local_variables.reject { |n| 
            Ignore.include? n.to_s 

          if locals.any?
            print "[#{pid}] locals:"
            puts { |n|
              [n, tp.binding.local_variable_get(n).inspect]

          # and finally the return value
          if tp.return_value.present?
            print "[#{pid}] returns:"
            puts tp.return_value.inspect


    def stop
      @tp.disable unless @tp.nil?

As per the code comments, the filtering is very specific to my project:

  • Only in development mode
  • Restricted to the :call and :return events
  • Must be a Class (this rule is currently relaxed)
  • The path must include my project app folder
  • Not interested in a bunch of (very frequent) messages (cache, user_session_check, etc.)

The TracePoint is only configured and enabled if the @tracing flag has been enabled. The start and stop methods are responsible for enabling, disabling, and configuring the TracePoint.


The next piece of the puzzle is trace_controller which handles requests to enable or disable the @tracing flag. There’s also a method to update the @filter:

return unless Rails.env.development?

class TraceController < ApplicationController

  def enable
    Tracing::Settings::Trace.tracing = true
    puts "tracing turned on in Process #{}"
    head :ok, content_type: "text/html"

  def disable
    Tracing::Settings::Trace.tracing = false
    puts "tracing turned off in Process #{}"
    head :ok, content_type: "text/html"

  def filter
    filter = params[:Filters]
    Tracing::Settings::Trace.filter = filter
    puts "tracing filter updated in Process #{}"
    head :ok, content_type: "text/html"


With a couple of new routes in routes.rb:

if Rails.env.development?
  get  'trace/on'        => 'trace#enable'
  get  'trace/off'       => 'trace#disable'
  post 'trace/filter'    => 'trace#filter'

Allowing us to make the following requests:


Trace Scripts

Since multiple worker processes are fired on start up, to ensure all instances of Trace are enabled or disabled, I use a few scripts to help me. They basically spam the same request in parallel. A third script updates the filter.

This is the first trace_on.rb:


require 'net/http'
require 'thread'

threads = []

10.times do 
  threads << do 
    Net::HTTP.get('localhost','/trace/on', 3000)

threads.each do |thread|

And the second, trace_off.rb:


require 'net/http'
require 'thread'

threads = []

10.times do 
  threads << do 
    Net::HTTP.get('localhost','/trace/off', 3000)

threads.each do |thread|

And the third script to configure the filter, trace_filter.rb:


require 'net/http'
require 'uri'
require 'json'
require 'thread'

criteria = [

body = {
  Filters: criteria

uri = URI.parse('http://localhost:3000/trace/filter')

threads = []

7.times do
  threads << do
    http =, uri.port)
    request =
      'Content-Type' => 'application/json')
    request.body = body
    response = http.request(request)

threads.each do |thread|

The reason I’m spamming the requests is to make sure all processes receive the updates. It doesn’t hurt if we send a couple of extras. Although each process has a TracePoint, because we are managing tracing via middleware, only one is ever active per request. The use case for this tracing is to capture detailed information about a specific user task we step through (i.e. new customer) not application performance profiling or tracking threading issues, etc.

After configuring the permissions:

chmod u+x trace_on.rb
chmod u+x trace_off.rb
chmod u+x trace_filter.rb

It’s simple to turn on tracing:


…to turn off:


…and to configure the filter:


When enabled, the Rails Server output should now contain the extra log information.

IDE Improvements

I’ve added a few buttons to the IDE to simplify working with the trace_controller:

In order for this to work, I had to add skip_forgery_protection to trace_controller.rb, and to allow unauthorized access to the controller in my application_controller.rb:

if Rails.env.development?
  return if params[:controller] == 'trace'

# rest of code to manage page access etc....

There’s a new basic filter configuration dialog. When I get some spare time, I’ll improve on it, but it is sufficient for now. The IDE takes care of the requests for me, there’s no need for the trace scripts:

So far, everything is working nicely, with the IDE capturing the server output:

Clicking on the logged items will perform some action, like jumping to the source file and line number, or showing the arguments in JSON format, etc. The vision is an interactive log.

But again, a word of caution. Ensure you filter unwanted events, as per your requirements. One event I captured logged to 900kb in size! It’s very verbose, so you want to capture just enough otherwise it becomes noise. I typically navigate proximate to the action I want to investigate, turn on the tracing, perform the action, then turn off tracing immediately.

Although I put guards around the code, I won’t be checking it into GitHub…this is staying on my local machine, I don’t fancy a 2am phone call from the boss about a production issue 🙂


This is my third attempt at this task, I’m now using middleware to manage the TracePoints across multiple processes. It’s running well, but if I find any problems, or a better way, I’ll be sure to update this post. It’s been a good opportunity to learn more about the Rails initialization process.

Although a bit dated, this Railscast is a nice introduction to middleware. This SO post was helpful. We’re using Rails 5.2, in earlier or later versions of Rails there may be initialization differences.

I hope you may have found this post useful.


Leave a Reply

Fill in your details below or click an icon to log in: Logo

You are commenting using your account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

Connecting to %s