st0012/object_tracer

ObjectTracer tracks objects and records their activities

ObjectTracer (previously called TappingDevice)

Introduction

As the name states, ObjectTracer allows you to secretly listen to different events of an object:

• Method Calls - what does the object do
• Traces - how is the object used by the application
• State Mutations - what happens inside the object

After collecting the events, ObjectTracer will output them in a nice, readable format to either stdout or a file.

Ultimately, its goal is to let you know all the information you need for debugging with just 1 line of code.

Usages

Track Method Calls

By tracking an object's method calls, you'll be able to observe the object's behavior very easily

Each entry consists of 5 pieces of information:

• method name
• source of the method
• call site
• arguments
• return value

Helpers

• print_calls(object) - prints the result to stdout
• write_calls(object, log_file: "file_name") - writes the result to a file
  • the default file is /tmp/object_tracer.log, but you can change it with log_file: "new_path" option

Use Cases

• Understand a service object/form object's behavior
• Debug a messy controller

Track Traces

By tracking an object's traces, you'll be able to observe the object's journey in your application

Helpers

• print_traces(object) - prints the result to stdout
• write_traces(object, log_file: "file_name") - writes the result to a file
  • the default file is /tmp/object_tracer.log, but you can change it with log_file: "new_path" option

Use Cases

• Debug argument related issues
• Understand how a library uses your objects

Track State Mutations

By tracking an object's traces, you'll be able to observe the state changes happen inside the object between each method call

Helpers

• print_mutations(object) - prints the result to stdout
• write_mutations(object, log_file: "file_name") - writes the result to a file
  • the default file is /tmp/object_tracer.log, but you can change it with log_file: "new_path" option

Use Cases

• Debug state related issues
• Debug memoization issues

Track All Instances Of A Class

It's not always easy to directly access the objects we want to track, especially when they're managed by a library (e.g. ActiveRecord::Relation). In such cases, you can use these helpers to track the class's instances:

• print_instance_calls(ObjectKlass)
• print_instance_traces(ObjectKlass)
• print_instance_mutations(ObjectKlass)
• write_instance_calls(ObjectKlass)
• write_instance_traces(ObjectKlass)
• write_instance_mutations(ObjectKlass)

Use with_HELPER_NAME for chained method calls

In Ruby programs, we often chain multiple methods together like this:

SomeService.new(params).perform

And to debug it, we'll need to break the method chain into

service = SomeService.new(params)
print_calls(service, options)
service.perform

This kind of code changes are usually annoying, and that's one of the problems I want to solve with ObjectTracer.

So here's another option, just insert a with_HELPER_NAME call in between:

SomeService.new(params).with_print_calls(options).perform

And it'll behave exactly like

service = SomeService.new(params)
print_calls(service, options)
service.perform

Installation

Add this line to your application's Gemfile:

gem 'object_tracer', group: :development

And then execute:

$ bundle

Or install it directly:

$ gem install object_tracer

Depending on the size of your application, ObjectTracer could harm the performance significantly. So make sure you don't put it inside the production group

Advance Usages & Options

Add Conditions With .with

Sometimes we don't need to know all the calls or traces of an object; we just want some of them. In those cases, we can chain the helpers with .with to filter the calls/traces.

# only prints calls with name matches /foo/
print_calls(object).with do |payload|
  payload.method_name.to_s.match?(/foo/)
end

Options

There are many options you can pass when using a helper method. You can list all available options and their default value with

ObjectTracer::Configurable::DEFAULTS #=> {
  :filter_by_paths=>[], 
  :exclude_by_paths=>[], 
  :with_trace_to=>50, 
  :event_type=>:return, 
  :hijack_attr_methods=>false, 
  :track_as_records=>false, 
  :inspect=>false, 
  :colorize=>true, 
  :log_file=>"/tmp/object_tracer.log"
}

Here are some commonly used options:

colorize: false

• default: true

By default print_calls and print_traces colorize their output. If you don't want the colors, you can use colorize: false to disable it.

print_calls(object, colorize: false)

inspect: true

• default: false

As you might have noticed, all the objects are converted into strings with #to_s instead of #inspect. This is because when used on some Rails objects, #inspect can generate a significantly larger string than #to_s. For example:

post.to_s #=> #<Post:0x00007f89a55201d0>
post.inspect #=> #<Post id: 649, user_id: 3, topic_id: 600, post_number: 1, raw: "Hello world", cooked: "<p>Hello world</p>", created_at: "2020-05-24 08:07:29", updated_at: "2020-05-24 08:07:29", reply_to_post_number: nil, reply_count: 0, quote_count: 0, deleted_at: nil, off_topic_count: 0, like_count: 0, incoming_link_count: 0, bookmark_count: 0, score: nil, reads: 0, post_type: 1, sort_order: 1, last_editor_id: 3, hidden: false, hidden_reason_id: nil, notify_moderators_count: 0, spam_count: 0, illegal_count: 0, inappropriate_count: 0, last_version_at: "2020-05-24 08:07:29", user_deleted: false, reply_to_user_id: nil, percent_rank: 1.0, notify_user_count: 0, like_score: 0, deleted_by_id: nil, edit_reason: nil, word_count: 2, version: 1, cook_method: 1, wiki: false, baked_at: "2020-05-24 08:07:29", baked_version: 2, hidden_at: nil, self_edits: 0, reply_quoted: false, via_email: false, raw_email: nil, public_version: 1, action_code: nil, image_url: nil, locked_by_id: nil, image_upload_id: nil>

hijack_attr_methods: true

• default: false
  • except for tap_mutation! and print_mutations

Because TracePoint doesn't track methods generated by attr_* helpers (see this issue for more info), we need to redefine those methods with the normal method definition.

For example, it generates

def name=(val)
  @name = val
end

for

attr_writer :name

This hack will only be applied to the target instance with instance_eval. So other instances of the class remain untouched.

The default is false because

1. Checking what methods are generated by attr_* helpers isn't free. It's an O(n) operation, where n is the number of methods the target object has.
2. It's still unclear if this hack safe enough for most applications.

ignore_private

Sometimes we use many private methods to perform trivial operations, like

class Operation
  def extras
    dig_attribute("extras")
  end

  private

  def data
    @data
  end

  def dig_attribute(attr)
    data.dig("attributes", attr) 
  end
end

And we may not be interested in those method calls. If that's the case, you can use the ignore_private option

operation = Operation.new(params)
print_calls(operation, ignore_private: true) #=> only prints the `extras` call

only_private

This option does the opposite of the ignore_private option does.

Global Configuration

If you don't want to pass options every time you use a helper, you can use global configuration to change the default values:

ObjectTracer.config[:colorize] = false
ObjectTracer.config[:hijack_attr_methods] = true

And if you're using Rails, you can put the configs under config/initializers/object_tracer.rb like this:

if defined?(ObjectTracer)
  ObjectTracer.config[:colorize] = false
  ObjectTracer.config[:hijack_attr_methods] = true
end

Lower-Level Helpers

print_calls and print_traces aren't the only helpers you can get from ObjectTracer. They are actually built on top of other helpers, which you can use as well. To know more about them, please check this page

Related Blog Posts

• Optimize Your Debugging Process With Object-Oriented Tracing and object_tracer
• Debug Rails issues effectively with object_tracer
• Want to know more about your Rails app? Tap on your objects!

Development

After checking out the repo, run bin/setup to install dependencies. Then, run rake spec to run the tests. You can also run bin/console for an interactive prompt that will allow you to experiment.

To install this gem onto your local machine, run bundle exec rake install. To release a new version, update the version number in version.rb, and then run bundle exec rake release, which will create a git tag for the version, push git commits and tags, and push the .gem file to rubygems.org.

Contributing

Bug reports and pull requests are welcome on GitHub at https://github.com/st0012/object_tracer. This project is intended to be a safe, welcoming space for collaboration, and contributors are expected to adhere to the Contributor Covenant code of conduct.

License

The gem is available as open-source under the terms of the MIT License.

Code of Conduct

Everyone interacting in the ObjectTracer project's codebases, issue trackers, chat rooms, and mailing lists is expected to follow the code of conduct.

object_tracer's Issues

Add with_print_calls method

Sometimes it's annoying to break a series of methods chain into several lines, just to call print_calls on an object. For example:

# we need to change this
SomeService.new(params).do_something

# into

s = SomeService.new(params)
print_calls(s)
s.do_something

For such cases, I'd like to add .with_print_calls method to the Object class. Then we can do

SomeService.new(params).with_print_calls.do_something

InitializationTracker's logic can cause error

Not every class respond to ancestors method.

      # InitializationTracker
      def filter_condition_satisfied?(tp)
        receiver = tp.self
        method_name = tp.callee_id

        if target.ancestors.include?(ActiveRecord::Base)
          method_name == :new && receiver.ancestors.include?(target)
        else
          method_name == :initialize && receiver.is_a?(target)
        end
      end

Refactor get_method_from_object

Support tag option

Sometimes we'll tap multiple objects at the same time and it'll be very useful to add tag to the payload/output messages to help determine the target. for example:

print_calls(seat_assignment_1, tag: "left assignment")
print_calls(seat_assignment_2, tag: "right assignment")

:x [left assignment] # SeatAssignment::GeneratedAttributeMethods
    from: /app/models/seat_picker.rb:228
    <= {}
    => 0

:x [right assignment] # SeatAssignment::GeneratedAttributeMethods
    from: /app/models/seat_picker.rb:230
    <= {}
    => 10

Support tracking ActiveRecord::Base instances by their ids

Currently, we track objects with their object_id. But for ActiveRecord::Base's instances, we can track them with record's id. This will allow us to track records from different places and don't need to trace where the object's initialized.

Add with_internal_states option

Besides arguments, sometimes internal states will affect a method's result too. But currently print_calls doesn't contain such information. So in such cases, users still need to dig into the method to check internal states.

Sample output:

:update? # CartOperationsService::OperationSet
    from: /Users/st0012/projects/ticketsolve/app/services/cart_operations_service.rb:102
    states:
     @price: 10.0
    <= {args: [], block: nil}
    => true

Support write_* helpers

print_* helpers prints the output to stdout directly, which can be hard to read when mixed with other log outputs. So we should also support write_* helpers that write all output into a designated file (default should be something like /tmp/tapping_device.log). And then users can do tail -f /tmp/tapping_device.log or cat /tmp/tapping_device.log with cleaner information.

write_calls(object)
write_traces(object)
write_mutations(object)

Provide options for tapping on call or return events

Right now it only listens to return events, which makes it possible to get a method call's return value but method calls' order may look confusing.
It should allow users to choose if they want to listen to call events instead. If the user doesn't need return_value and cares about calls' order more, he/she should be able to do it.

Use Method#source to replace Payload#method_head’s implementation

Filter Out Entries From TappingDevice

When using something like

print_calls(self)

It prints the print_calls call. Which should be filtered out

:print_calls # TappingDevice::Trackable
    from: /Users/st0012/projects/ticketsolve/app/controllers/api/ticketoffice/v1/view_download_options_controller.rb:6
    <= {target: #<Api::Ticketoffice::V1::ViewDownloadOptionsController:0x00007fc667e63f90>, options: {filter_by_paths: [], exclude_by_paths: [], with_trace_to: 50, root_device: #<TappingDevice:0x00007fc667f0b0d8>, event_type: return, descendants: [], track_as_records: false}}
    => #<TappingDevice:0x00007fc667f0b0d8>

inspect:true not working for activerecord

:mutations_from_database (private) # ActiveModel::Dirty
from: /var/lib/gems/2.7.0/gems/activerecord-6.0.3.4/lib/active_record/attribute_methods/dirty.rb:161
changes:
@mutations_from_database: [undefined] =>
#ActiveModel::AttributeMutationTracker:0x00007f9ee9963040

my questions:

1. how to make #ActiveModel::AttributeMutationTracker:0x00007f9ee9963040 to be inspect, (looks like inspect: true) not working?
2. whats best practise to trace one field of the ActiveModel

Don't tap on the same object repeatedly

It should be smart enough to tap on an unique instance just once, especially in a Rails application where files will be auto-reloaded.

class PostsController
  print_instance_traces(self)
end

Add tap_on_mutation!

tap_on_mutation! can track method calls that change certain object's state, e.g. updating instance variables. This can be very useful for certain cases.

However, for objects like AR records, we need to provide a way to specify what internal states to track (maybe just attributes).

feature request: can add one more option to watch the specific field to track the change

like print_instance_mutations(Spree::Order, watch: :price) then all price changes will print

Use pastel in output payload

https://github.com/piotrmurach/pastel

Colorize output of tracing helpers

Rename to ObjectTracer?

TappingDevice doesn't convey the idea of the gem very well. But ObjectTracer seems to be a very good name for that purpose.

Some Ruby built-in methods don't trigger TracePoint

List: https://github.com/ruby/ruby/blob/41a4c80d284a24360d3a6c5b6e5ca408ccca6efc/bootstraptest/test_insns.rb
Related Post: https://thomasleecopeland.com/2017/04/05/tracepoint-and-array-size.html

Global Configuration

Adding options in every helper call can by annoying, we should have something like

TappingDevice.config[:exclude_by_paths] = [/gems/]
TappingDevice.config[:with_traces_to] = 10

Add ignore_private option

Assume we have a class like:

class Operation
  def extras
    dig_attribute("extras")
  end

  private

  def data
    @data
  end

  def dig_attribute(attr)
    data.dig("attributes", attr) 
  end
end

Every time we call extras, it'll call dig_attribute and data as well. So the output of print_calls(operation) would look like this

As you can see, the entries of private helpers like data and dig_attribute provide duplicated or redundant information.

So we should have an option to filter out calls of private helpers.

print_calls(operation, ignore_private: true)

Add print_mutations

Tapping any instance of class

Hello.

Some additional methods (or options) would be helpful for tapping any instances of specific class.

Example: print_calls_of_any_instance(MyClass).

Handful for cases when you can't access all objects, like internal work of ORM, or it'd be ugly.

Support limiting tracing helper's scope

With a Block

print_calls_in_detail(ActionDispatch::Http::URL) do
  ActionDispatch::Http::URL.url_for(host: "www.ror.co.uk", subdomain: "api", tld_length: 2)
end

# ignore what happens outside the block

With stop_tracing

print_calls_in_detail(ActionDispatch::Http::URL)
result = ActionDispatch::Http::URL.url_for(host: "www.ror.co.uk", subdomain: "api", tld_length: 2)

stop_tracing # ignore what happens after this line