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.

Middleware

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:

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

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

config.middleware.use TracingMiddleware

Tracing

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 = 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"

      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 - 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 = 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
      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 (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.

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 us to make the following requests:

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

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:

#!/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 the second, trace_off.rb:

#!/usr/bin/ruby

require 'net/http'
require 'thread'

threads = []

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

threads.each do |thread|
  thread.join
end

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

#!/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. 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:

./trace_on.rb

…to turn off:

./trace_off.rb

…and to configure the filter:

./trace_filter.rb

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

# 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 🙂

Conclusion

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.

Advertisement