Tracing in Rails

Whilst working on a Ruby on Rails 5.1 legacy codebase—recently updated from version 4—I really needed some help with debugging. TracePoint was perfect for the job.

TracePoint is "a class that provides the functionality of Kernel#set_trace_func in a nice Object-Oriented API."

But you have to be judicious. You can bring your application to a grinding halt if you process too many events.

I wanted to track method entry and exit using the :call and :return events.

TracePoint allows you to access the current binding, so you can grab argument names and values, local variable values, and the return value. That's a lot of useful information.

---

Middleware

I settled on a solution that activates tracing per request—if tracing is enabled. Managing multiple processes and instances of TracePoint was quite challenging, I needed to add app\middleware\tracing_middleware.rb:

return unless Rails.env.development?

class TracingMiddleware
  def initialize(app)
    @app = app
  end

  def call(env)
    Tracing::Settings::Trace.start
    status, headers, response = @app.call(env)

    Tracing::Settings::Trace.stop
    [status, headers, response]
  end
end

And to append this line to config\environments\development.rb:

config.middleware.use TracingMiddleware

---

Tracing

To configure a TracePoint, 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 = Settings.new

    attr_accessor :tracing, :filter

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

    def start
      return if @tracing.blank?

      unless @tp.nil?
        @tp.enable
        return
      end

      puts "[#{Process.pid}] configuring trace"

      # set up a default filter to ignore noise
      if @filter.blank?
        puts "[#{Process.pid}] using default filter"

        @filter = [
          'cache',
          'tenant',
          'user_database_connector',
          'coredatabase',
          'module_permission',
          'user_session_check',
        ];
      end

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

      # source must be a class - commented out 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 = Process.pid
      puts "[#{pid}] #{path} [#{tp.event}]"

      #examine the call event and grab the arguments
      if tp.event == :call
        args = tp.parameters.map(&:last).reject { |n| Ignore.include? n.to_s }

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

      # 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 locals.map { |n| [n, tp.binding.local_variable_get(n).inspect] }.to_h
        end

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

      @tp.enable
    end      

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

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 messages (cache, session, 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.

---

Controller

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 
  skip_forgery_protection 
  
  def enable 
    Tracing::Settings::Trace.tracing=true
    puts "tracing turned on in Process #{Process.pid}" 
    head :ok, content_type: "text/html" 
  end 
  
  def disable
    Tracing::Settings::Trace.tracing=false 
    puts "tracing turned off in Process #{Process.pid}" 
    head :ok, content_type: "text/html" 
  end 
  
  def filter 
    filter=params[:Filters] 
    Tracing::Settings::Trace.filter=filter
    puts "tracing filter updated in Process #{Process.pid}" 
    head :ok, content_type: "text/html" 
  end 
end

---

Routes

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'
end

Allowing the following requests:

http://localhost:3000/trace/on
http://localhost:3000/trace/off
http://localhost:3000/trace/filter

---

Trace Scripts

To ensure all instances of Trace are enabled or disabled, I use a few scripts to help me.

The first is trace_on.rb:

#!/usr/bin/ruby

require 'net/http'
require 'thread'

threads = []

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

threads.each do |thread| 
  thread.join 
end

And similarly, trace_off.rb, the only code difference is the endpoint:

Net::HTTP.get('localhost','/trace/off', 3000)

And lastly, trace_filter.rb, to configure the filter:

#!/usr/bin/ruby

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

criteria = [
  'replace_html_reserved',
  'user_database_migrator',
  'login_helper',
  'desktop_hour',
  'database_corrector',
  'escape_field_alias'
];

body = { Filters: criteria }.to_json

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

threads = []

7.times do
  threads << Thread.new do 
    http=Net::HTTP.new(uri.host, uri.port) 
    
    request=Net::HTTP::Post.new(uri.request_uri, 'Content-Type' => 'application/json')

    request.body = body
    response = http.request(request)
  end
end

threads.each do |thread|
  thread.join
end

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. 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 manage the filtering:

./trace_on.rb
./trace_off.rb
./trace_filter.rb

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

But again, a word of caution. Ensure you filter unwanted events, as per your requirements. It can be 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 it off immediately.

---

Conclusion

This was the third attempt, 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 the 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. And this post was also helpful.