Writing a Tracing Framework, Part 2: The API

Note: This post has been in my drafts folder for the past 5+ years. All the concepts should have survived any intervening bitrot, so I’m dusting it off and trying to bring the series roughly up to parity with the source code I wrote so long ago, since I think the material is still interesting.

In part 1 we got basic structured events working: create an event object, add fields to it, and fire it to the backend when it’s done. But doing this by hand is at best cumbersome, if not error-prone. A good tracing framework would have an ergonomic way of managing the events under construction. In this post, we’ll develop the fundamental API that will serve us as we build out additional tracing functionality.

The Problem

Generating events relies on a one-two punch: every event that gets created needs to be “released” by calling Minitrace::Event#fire.

event = Minitrace::Event.new
# ...
event.fire

Part of the intervening code’s job is to add fields to the event. In practice, though, this is going to be interleaved with the actual logic of your program as well. This introduces a few problems.

First, on a touchy-feely level, it’s pretty hard to enforce this two-step contract manually. At least in Ruby, there’s no error we can raise if the user forgets to fire the event. The Minitrace::Event object will just hang out in memory until it gets garbage collected, and forgetting to fire the event becomes more likely as the intervening code grows longer & more complex. The further away the event.fire call site has to be from the initialization, the easier it’ll be for that step to slip out of the programmer’s working memory altogether.

More concretely, the stuff in between the create/fire steps has its own arbitrary logic. The code itself might inadvertently prevent the #fire call from ever happening! For instance, there could be an early return statement, or an exception could be raised. We can protect against these with an ensure statement, but that introduces even more boilerplate:

event = Minitrace::Event.new
begin
  # ...
ensure
  event.fire
end

So to start, we want to encapsulate this pattern into one method that handles both the setup and the teardown of the event without the extra code.

Wrapping Events

This type of setup/teardown pattern occurs frequently enough in programming writ large that different languages usually have their own features for handling it. With Ruby, we’ll pass our program’s code as a block to some high-level Minitrace.with_event method, which can then be responsible for the actual event plumbing. This gives us an API where we can clearly wrap sections of business logic like so:

Minitrace.with_event do
  puts "hello world"
end

Basically all it takes to get this example to work is to copy the previous boilerplate into a method definition:

module Minitrace
  class << self
    def with_event
      event = Minitrace::Event.new
      yield
    ensure
      event.fire
    end
  end
end

Prior to executing the block (which is tacitly an argument to all methods in Ruby), a new Minitrace::Event instance is created. Then yield invokes the block, causing the code to evaluate and print “hello world”. After that’s done, we fire the event to the backend. The last step happens within an ensure, which keeps it safe from any uncaught exceptions in the block. It also doesn’t affect the return value of the method, so Minitrace.with_event { blob } will return the same value as blob.

It’s idiomatic to use blocks like this in Ruby, but the same basic idea applies to other languages. In Python, we could implement this using the with statement and a custom context manager, per PEP 343:

with minitrace.event():
    print("hello world")

Really, anything with first-class functions (or an approximation thereof) could express it similarly. For instance, you could use a callback in NodeJS:

minitrace.withEvent(() => {
  console.log("hello world");
});

It might be typical in some languages to split the setup/teardown into more of a two-step process, like with Go and its “defer” statement, but it effectively accomplishes the same goal:

func main() {
	minitrace.StartEvent()
	defer minitrace.FinishEvent()
	fmt.Println("hello world")
}

Still other languages can tie custom logic to object destructors in patterns such as RAII. For example, in Rust our method could return a special guard object; once that object goes out of scope, we’d fire the event via the Drop trait. As of this writing, this is exactly how it works in the tracing crate with its Entered struct.

At any rate, the idiom afforded by our particular language lets us clearly mark where an event starts and finishes. But the main thing this Ruby version lacks is any way to access the event we just created! The Minitrace::Event instance exists as a local variable inside the Minitrace.with_event method, so our block won’t be able to reference it to add fields.

A simplistic solution would be to pass an argument to the block via yield:

     module Minitrace
       class << self
         def with_event
           event = Minitrace::Event.new
-          yield
+          yield event
         ensure
           event.fire
         end
       end
     end

Then the block gains access to the Minitrace::Event instance as its own local variable:

Minitrace.with_event do |event|
  event.add_field("field", "value")
  puts "hello world"
end

However, passing around this variable leads to organizational issues in the application code.

Passing Events

Let’s consider a hypothetical code base for a social media site where user accounts can be deactivated. We can imagine a lot of business logic this might entail: hiding all the user’s comments, invalidating their login credentials, recording the action in a moderation log, etc. Maybe we even email a special link to the user in case they want to reactivate their account, but only if the account satisfies certain criteria (e.g., so that spammers aren’t allowed to reactivate).

Naturally, as code becomes more complex, we break the logic up into distinct chunks. Blocks of code get factored into separate methods, methods get factored into separate classes, classes get factored into separate libraries. Any “real” program weaves its way through a whole web of control flow. So our User#deactivate method might look something like this:

class User
  def deactivate
    self.active = false
    hide_comments
    update_moderation_log
    reset_credentials
    # ...
    send_reactivation_email if can_reactivate?
  end
end

The helper methods could then farm out their work to further methods, and even to other classes. For example, there might be a laundry list of conditions for the User#can_reactivate? predicate:

class User
  def can_reactivate?
    return false if banned?
    return false if karma < 0
    return false if SpamDetector.check(self)
    # ...
    true
  end
end

Now, let’s say we want to fire an event each time a user account is deactivated. Despite all the intermediary logic, this can still be seen as one unit of work to be represented as a single event. This is deceptively important: though events follow the structure of the code pretty intimately, they needn’t follow it exactly. Otherwise, we might as well just have one event per line of code. In reality, one event might represent work that’s spread over many lines, methods, classes, or libraries—whatever granularity is meaningful for our trace.

Using the event-yielding version of our Minitrace.with_event method, we could arrange for access to a local variable in the body of User#deactivate:

class User
  def deactivate
    # 1. Event is created at the beginning of the block
    Minitrace.with_event do |event|
      # 2. We can add the desired fields
      event.add_field("action", "User#deactivate")
      event.add_field("timestamp", Time.now)
      # ...

      # 3. Actual business logic
      self.active = false
      hide_comments
      update_moderation_log
      reset_credentials
      # ...
      send_reactivation_email if can_reactivate?
    end
    # 4. Event is fired to the backend at the end of the block
  end
end

The problem is that the event variable is out of scope everywhere outside the .with_event block, even though interesting things might happen downstream in the call graph. The whole appeal of tracing is adding as much context as we can to our structured event: how many comments were hidden? does the moderation log show that the account was previously deactivated? how long has it been since the user last logged in with their current credentials? did we send a reactivation email? if not, what was the reason (banned, negative karma, spammer, …)? and so on.

Unless we inline or duplicate all the helper methods’ logic into the top-level User#deactivate (where event is in scope), we won’t be able to collect this metadata. We could instead pass event as a new parameter to those helper methods, but that gets quite intrusive:

class User
  def deactivate
    Minitrace.with_event do |event|
      # Have to pass the event everywhere...
      self.active = false
      hide_comments(event)
      update_moderation_log(event)
      reset_credentials(event)
      # ...
      send_reactivation_email(event) if can_reactivate?(event)
    end
  end

  # ...

  # Now all the method signatures get bogged down!
  # Does it make sense that this predicate takes *any* parameters?
  def can_reactivate?(event)
    # Do we need to keep passing the event forward to {User#banned?}?
    if banned?
      event.add_field("cannot_reactivate", "banned")
      return false
    end
    # What about to {User#karma}?
    if karma < 0
      event.add_field("cannot_reactivate", "negative karma")
      return false
    end
    # What about to {SpamDetector.check}?
    if SpamDetector.check(self)
      event.add_field("cannot_reactivate", "spammer")
      return false
    end
    # ...
    true
  end
end

As I hope you’ll agree, weaving this parameter throughout our entire code base is clunky at best.

Really, it’s not the application code’s responsibility to track this state. So instead, we’re going to devise a minitrace API that lets you incrementally build an event no matter how your program is factored out.

A Better Idea

Essentially, the issue is that we have nowhere to store the event currently under construction. The easiest fix would be to define another module-level attribute on Minitrace akin to Minitrace.backend:

module Minitrace
  class << self
    # Is this what we want?
    attr_accessor :current
  end
end

That way, we wouldn’t have to pass around a Minitrace::Event instance. Just stash it in Minitrace.current then call Minitrace.current.add_field(...) as needed. It’d basically be a designated global variable.

However, this quickly falls apart under scrutiny. It’s only one variable, so it locks us into finishing one event before we can start another. Say we’re in the middle of deleting a user, but then we trigger a condition that sends a notification email. If we wanted to record an extra event for that notification, we’d need to wait until the user deletion was done before we could assign a new event to this proposed Minitrace.current attribute. And what if there are multiple events in the middle of the deletion? Or further events within the notification process?

Instead, we want a mechanism where we can be working on one event A, switch gears to another event B, then go back to A when we’re done. At any given time, we’re only working on one event. But we still keep track of events in progress, where the first one we started is the last one we finish. This should sound familiar to programmers, because we use such a data structure every day: the call stack.

With the call stack, each individual entry—called a stack frame—holds onto the context of a single function call. So while we’re running function A, we’ll have a corresponding stack frame where we can stash any data that’s specific just to this function invocation, such as local variable bindings. When function A calls another function B (or even calls itself recursively!), we allocate a new frame and push it onto the stack. As B executes, it’s only affecting the current frame sitting at the top of the stack. Once B finishes, we pop its frame and resume executing A, whose context is once again available at the top of the stack.

We can borrow this same pattern for our event bookkeeping. Whereas the call stack holds onto frames, our stack will store events that have yet to be fired.

Stacked Events

Instead of yielding a single event, we’ll revise Minitrace.with_event to interact with a stack of events:

module Minitrace
  class << self
    def events
      @events ||= []
    end

    def with_event
      events << Minitrace::Event.new
      yield
    ensure
      events.pop.fire
    end
  end
end

The Minitrace.events method is a getter for the @events variable, which is an array of Minitrace::Event instances. By default, it’s empty. The leftmost array element (at index 0) will be the bottom of the stack, while the rightmost element will be the top.

We tacitly synchronize the flow of events onto and off of this stack via Minitrace.with_event. Entering the block pushes an event to the stack, exiting the block pops the stack and fires that event. This allows for nested blocks where events won’t interfere with each other:

Minitrace.with_event do
  # 1. Push event; stack now = [outer]
  puts "starting outer block"
  Minitrace.with_event do
    # 2. Push event; stack now = [outer, inner]
    puts "starting inner block"
  end
  # 3. Pop event = inner and fire; stack now = [outer]
  puts "finished inner block"
end
# 4. Pop event = outer and fire; stack now = []
puts "finished outer block"

Adding Fields

Now that we have this stack of events, we can define module-level methods that delegate to the top event as the one we currently care about:

module Minitrace
  class << self
    def add_field(field, value)
      events.last&.add_field(field, value)
    end

    def add_fields(fields)
      events.last&.add_fields(fields)
    end
  end
end

Note that we look at the top of the stack by looking at the last element in the array (the rightmost position). However, if the array is empty, this will be nil. So we also use Ruby’s safe navigation operator, which means we can call these methods even when there are no events on the stack.

In action:

Minitrace.add_field("no", "effect")

Minitrace.with_event do
  Minitrace.add_field("start", "a")

  Minitrace.with_event do
    Minitrace.add_fields("start" => "b", "finish" => "b")
  end

  Minitrace.add_field("finish", "a")
end

Each Minitrace.with_event scopes the Minitrace.add_field & Minitrace.add_fields methods to a new event within that block. This example generates two events, which we can spy on from our backend:

Minitrace.backend.processed.map(&:fields)
#=> [{ "start" => "b", "finish" => "b" }, { "start" => "a", "finish" => "a" }]

Notice that the events are processed as the stack is popped, so event B fires before event A. This “last in, first-out” ordering will be very important to keep in mind as we go forward in this series.

Up Next

This is pretty much the shape we want for minitrace’s API! It eliminates the setup/teardown boilerplate in an idiomatic way and lets us add fields to the current event without threading a bunch of state through our application code. However, there is still a subtle use case where we can’t always rely on the looking at just one event at a time. In the next installment, we’ll dig into that problem.

You can find the commit corresponding to this post’s code on GitHub:

• 8ad5449 Define module-level API for synchronous events