Forem: Julik Tarkhanov

Improve Your Life with Long Error Messages

Julik Tarkhanov — Wed, 29 Sep 2021 13:23:46 +0000

It is incredibly helpful to quickly detect when a customer encounters an error and where the error originated from in your source code. Thankfully, this is where many interpreted languages shine. They always include a complete backtrace — the path where the call was made, which caused the error to be raised (or thrown).

In AppSignal, any error alert will bring you to an incident detail page that shows you that backtrace. With a Github or Gitlab integration, you can immediately jump from an error to the place to solve it.

Beyond that, however, we can make our errors more useful — with a little bit of prose.

The Three Main Questions an Error Message Must Answer

Folks who are old enough will likely remember this screen from the days of old (pre-UNIX) MacOS:

It told us only one thing: your work is over, it's time to reboot the machine. But it took me some time to figure out why this error was so particularly frustrating — it would not answer any of the "big three" questions I believe an error must satisfy:

What happened?

Not "a catastrophic failure", but what exactly happened? Did the flux capacitor overcombobulate the particle instigator? Was a certain parameter above (or below) an acceptable value? Was a piece of incorrect user input to blame? The error should explain what happened.

Where did it happen?

Was it QuickTime Player that crashed my machine? Was it this new USB mouse driver that I have just installed?

The error should explain where it originated. Not where it happened exactly in the code — the backtrace usually covers this part — but which high-level component it stems from. If your WindowServer crashes on macOS, it is not that hard to understand that your entire UI has crashed because WindowServer is the process that owns and manages everything on screen. But which application caused WindowServer to crash?

What can I do to make the error go away?

Did invalid input cause it? Maybe we are trying to access some data that is, for example, no longer available, and we could catch this access attempt at a higher level of the stack? Or maybe we have a client that sends invalid input and always leads to this error? The error should do its best to tell us how to prevent it from happening again.

Item 4 on this list would be "automatic recovery" and it becomes relevant when multiple systems know of the same error semantics and try to recover from them in a distributed way. This can be a great topic for a future article.

Optimizing Your Error for the Reader

Take a look at this error as you would see it in AppSignal:

It gets raised by a popular Ruby gem called circuitbox. This gem implements the famous Circuit Breaker pattern in Ruby.

A short summary of what circuit breakers do:

If you call an external service (a web service API, database, or cloud storage system), your call might fail. If the service you are calling is down for a long time, all of your calls will fail, and you will be bombarding this service with calls and connection attempts.
To allow your application to proceed regardless — and to avoid the service you are calling from getting overloaded — a so-called "circuit breaker" gets inserted between your application (the caller) and the service your application calls (the callee).
Should N consecutive calls from the caller to the callee fail, the circuit breaker will "open" and forbid any subsequent calls from going through, failing these calls rapidly.
After some time, the circuit breaker will attempt to "close" and allow calls through. If the callee has recovered by then, normal operation will resume.

Once you start using multiple services, having a circuit breaker becomes an absolute necessity. Sometimes, you need several circuit breakers — one for each service you call (or for each host you call, depending on the situation). A particular service that you call might be responsive, while another might be having a bad time.

Circuitbox provides such a wrapper, and when a service you are calling isn't working (for some time), the circuit breaker is open. The gem raises an exception to indicate that the call isn't allowed to go through.

Let's examine this error against the "big three" questions I mentioned above:

What happened?

Well, a call to a service tripped a circuit breaker — some circuit breaker. One could say that this satisfies the What? question, although for me, it would be constructive to know what the originating error was. This error is derived (or a wrapper, if you will). It gets raised once some other error (the one causing the original service failure) happens for some time. That's the error I would expect to see in the message.

Where did it happen?

The error does have a backtrace, and if we follow it closely, we find some clues as to where it has originated. The application this was lifted from produces a backtrace of 34 levels for this error, and the spot where the circuit breaker is called from is located on line 4.

It does not tell us which service we were calling or how long the service was inoperable. So it certainly does not fulfill the where part and makes investigation harder. What would help is for the error to tell us in which service it originated — what were we calling when it happened?

What can I do to make the error go away?

This error does not tell us what we can do to re-establish operation. At first glance, it would seem that it never could — a remote service does not respond, nobody knows when it could recover. So, preventing it from happening again seems to be off the table.

But think again: we could know, for example, that the service hasn't responded for 30 seconds, or that it has been down four times in the last 24 hours — which would enable us to contact the service owners and ask them about their SLOs.

More importantly, in this particular case, the error led to a developer attempting to do an incorrect bug fix. This is a fairly real danger for errors that seem severe but do not answer the three main questions. Bear in mind, when you are handling errors, you will often be in a stressful situation. It might be that your application is overloaded and you need to get it fixed quickly. Or it might be that your business depends on this transaction taking place and the circuit breaker is in the hot path of the transaction.

In our specific situation, an engineer attempted to capture all calls and forbid outgoing HTTP requests to a specific hostname because they assumed that the circuit breaker covered calls to all hosts handled by a code path. They did not know that the service name for the circuit breaker was specific to the hostname we were calling and that the circuit breaker tripped for external service A did not mean that it also tripped for service B. This is the price of error messages that are not informative enough.

So, although a circuit breaker is practical, this error message could use some TLC. Let's see where we can make improvements.

Adding More Context to the Error with Heredocs

The first — and easiest — change we can make is to explain the meaning of this error. We start with just the class name. It can be very descriptive — for example, ActiveRecord::RecordNotFound is a reasonably descriptive class name for an exception. Circuitbox::CircuitOpen is pretty good in that regard — it does communicate the error condition to us.

The next part to look at is the error message. When you initialize an object that subclasses Exception in Ruby, you can pass a data string to include as the error message. The message is then available under the Exception#message method:

raise ServiceUnavailable, "The service you were trying to call was unavailable"`

Let's apply those patterns to our open circuit message:

raise CircuitOpen, <<~EOM
  The circuit breaker is open. This means that the service you are calling has been unavailable or has been timing out
  for some time, and the circuit breaker has opened to prevent your application from slowing down and to protect the
  service you are calling from the thundering herd of requests once it recovers.
EOM

This gets us a notch closer to fulfilling question 1 — telling what happened. Now the error will be understandable for someone who doesn't know what the circuitbox gem does or what its various exceptions mean. This speeds up debugging. But we can still take this further!

Taking It a Notch Further with Dynamic Data

For some inspiration, we can look at ActiveRecord::RecordNotFound error message:

Couldn't find Batch with 'id'=14082

This error message communicates a few crucial bits of information, namely:

Which model we were trying to find (in this case,Batch)
Which row we were looking for (in this case, the row with the id of 14082)

This gets us way closer to fulfilling the second and third questions. It tells us where it happened (somewhere where we were looking for a Batch with the id of 14082) but also, to an extent, what we can do to prevent it from happening again. We need to find where code similar to this gets executed in one of our backtrace lines or close to them:

Batch.find(id)

But if we look at other examples from Rails, we can see some more useful error messages there. For example, the famous "whiny nil" extension tells you when you mistakenly try to obtain the id of a nil value:

Called id for nil, which would mistakenly be 4 -- if you really wanted
the id of nil, use object_id

We are not limited to specifying the error messages with single-line strings, we can also use heredocs - a multiline string preformatted with line breaks. While quite a few people use heredocs in Ruby, there is one feature in them that often gets forgotten, namely, heredocs support the same string templating as double-quoted strings do! So, just as we can do this:

raise CircuitOpen, "Service #{@service} was unresponsive"

we can do the same in a longer chunk of text with a heredoc:

raise CircuitOpen, <<~EOM
  The circuit breaker for the service #{@service.inspect} is open.

  This means that the service you are calling has been unavailable or has been timing out
  for some time, and the circuit breaker has opened to prevent your application from slowing down, as well as to protect the
  service you are calling from the thundering herd of requests once it recovers.
EOM

Note how I use inspect for the string templating so that the literal value of a variable is automatically displayed in quotes and is visually separated (delimited) from the rest of the message. This makes it easier to distinguish the dynamically generated part of the message from the written prose.

Enhancing the Display with Structured Data

Often, errors are caused by specific user input. Since we can include arbitrary programmatic strings in our error messages, nothing prevents us from having relevant user input in the error message (if we know that input can be useful). We can make this input fit for human consumption using something like JSON.pretty_generate:

raise MyError, <<~EOM
  Fields were provided for validation which didn't match the schema. The input was:

  #{JSON.pretty_generate(params[:transaction_details]}
EOM

For example, in one of WeTransfer's applications, we have a well-known failure condition that creates a specific pattern of invalid input. Since we know this error only emerges in the face of that input, we inject it into the error message. Here's what that error message in AppSignal then looks like:

Be careful with that pattern though: the data inside your exception message is subject to data protection laws, just like any other personally identifiable information.

If you do template your input into the error messages, you might need to ensure that you are permitted to send it to services such as AppSignal. As the data is inside the error message, it can no longer be automatically anonymized or scrubbed.

Conclusion: The What, Where, and Why of Errors

You want your errors to tell you what happens, where and why they happen, in a form that requires as little investigation as possible.

Long error messages are a great way to achieve that and provide you with considerable benefits at a small up-front cost. Just write that error message!

Julik Tarkhanov is a VFX artist gone rogue and Ruby. By day and night he toots the horn at the WeTransfer OSS repos like ZipTricks.

WeTransfer is one of our long-time users. Read more about the smart ways they've used AppSignal in our case study.

Fibers and Enumerators in Ruby: Turning Blocks Inside Out

Julik Tarkhanov — Tue, 27 Nov 2018 14:01:36 +0000

Ruby has various ways of performing iteration—loops, blocks and enumerators. Most Ruby programmers are at least familiar with loops and blocks but Enumerator and Fiber often stay in the dark. In this edition of Ruby Magic, guest author Julik shines a light on Enumerable and Fiber to explain flow controlling enumerables and turning blocks inside out.

Suspending Blocks and Chained Iteration

We've discussed Enumerator in a previous edition of Ruby Magic, where we described how to return an Enumerator from your own #each method and what it can be used for. An even broader use case for Enumerator and Fiber is that they can "suspend a block" mid-flight. Not just the block given to #each or the entire call to #each, but any block!

This is a very powerful construct, which can be used to implement shims for methods that work by using blocks as a bridge to callers that expect sequential calls instead of taking a block. For example, imagine we want to open a database handle and read each item that we have retrieved:

db.with_each_row_of_result(sql_stmt) do |row|
  yield row
end

The block API is great since it will potentially perform all kinds of cleanup for us when the block is terminated. However, some consumers might want to work with the database in this way:

@cursor = cursor

# later:
row = @cursor.next_row
send_row_to_event_stream(row)

In practice, it means we want to "suspend" the execution of the block "just for now" and carry on later within the block. Thus, the caller takes over the flow control instead of it being in the hands of the callee (the method performing the block).

Chaining Iterators

One of the most common uses of this pattern is chaining multiple iterators together. When we do so, the methods we are used to for iteration (like #each), return an Enumerator object instead, which we can use to "grab" the values that the block sends us using the yield statement:

range = 1..8
each_enum = range.each # => <Enumerator...>

The enumerators can then be chained which allows us to perform operations like "any iteration but with the index". In this example, we're calling #map on a range to get an Enumerable object. We then chain #with_index to iterate over the range with an index:

(1..3).map.with_index {|element_n, index| [element_n, index] }
#=> [[1, 0], [2, 1], [3, 2]]

This can be very useful, especially if your system uses events. Ruby provides a built-in method for wrapping any method with an Enumerator generator, which allows us to accomplish exactly this. Imagine we want to "pull" rows one by one from our with_each_row_of_result, instead of the method yielding them to us.

@cursor = db.to_enum(:with_each_row_of_result, sql_stmt)
schedule_for_later do
  begin
    row = @cursor.next
    send_row_to_event_stream(row)
  rescue StopIteration # the block has ended and the cursor is empty, the cleanup has taken place
  end
end

If we were to implement this ourselves, this is how it would likely come about:

cursor = Enumerator.new do |yielder|
  db.with_each_row_of_result(sql_stmt) do |row|
    yielder.yield row
  end
end

Turning Blocks Inside Out

Rails allows us to assign the response body to also be an Enumerator. It will call next on the Enumerator we assign as the response body and expect the returned value to be a string—which will be written out into the Rack response. For example, we can return a call to the #each method of a Range as a Rails response body:

class MyController < ApplicationController
  def index
    response.body = ('a'..'z').each
  end
end

This is what I call turning a block inside out. In essence, it is a control flow helper that allows us to "freeze time" in a block (or a loop, which is also a block in Ruby) mid-flight.

However, Enumerators have a limiting property that makes them slightly less useful. Imagine we want to do something like this:

File.open('output.tmp', 'wb') do |f|
  # Yield file for writing, continuously
  loop { yield(f) }
end

Let's wrap it with an enumerator, and write into it

writer_enum = File.to_enum(:open, 'output.tmp', 'wb')
file = en.next
file << data
file << more_data

Everything works great. However, there is a hitch—how do we tell the enumerator that we are done writing, so that it can "finish" the block, close the file and exit? This will perform a number of important steps—for example, resource cleanup (the file will be closed), as well as ensuring all the buffered writes are flushed to disk. We do have access to the File object, and we can close it ourselves, but we would like the enumerator to manage the closing for us; we have to let the enumerator proceed past the block.

Another hurdle is that sometimes we want to pass arguments of what is happening within the suspended block. Imagine we have a block-accepting method with the following semantics:

write_file_through_encryptor(file_name) do |writable|
  writable << "Some data"
  writable << "Some more data"
  writable << "Even more data"
end

but in our calling code we want to use it like this:

writable = write_file_through_encryptor(file_name)
writable << "Some data"
# ...later on
writable << "Some more data"
writable.finish

Ideally, we would wrap our method call into some structure that would permit us the following trick:

write_file_through_encryptor(file_name) do |writable|
  loop do
    yield_and_wait_for_next_call(writable)
    # Then we somehow break out of this loop to let the block complete
  end
end

What if we were to wrap our writes like this?

deferred_writable = write_file_through_encryptor(file_name)
deferred_writable.next("Some data")
deferred_writable.next("Some more data")
deferred_writable.next("Even more data")
deferred_writable.next(:terminate)

In this case, we will use the :terminate as a magic value that will tell our method that it can finish the block and return. This is where Enumerator won't really help us because we can't pass any arguments to Enumerator#next. If we could, we would be able to do:

deferred_writable = write_file_through_encryptor(file_name)
deferred_writable.next("Some data")
...
deferred_writable.next(:terminate)

Enter Ruby's Fibers

This is exactly what Fibers permit. A Fiber allows you to accept arguments on each reentry, so we can implement our wrapper like so:

deferred_writable = Fiber.new do |data_to_write_or_termination|
  write_file_through_encryptor(filename) do |f|
     # Here we enter the block context of the fiber, reentry will be to the start of this block
    loop do
      # When we call Fiber.yield our fiber will be suspended—we won't reach the
      # "data_to_write_or_termination = " assignment before our fiber gets resumed
      data_to_write_or_termination = Fiber.yield
    end
  end
end

This is how it works: When you first call .resume on your deferred_writable, it enters the fiber and goes all the way to the first Fiber.yield statement or to the end of the outermost Fiber block, whichever comes first. When you call Fiber.yield, it gives you back control. Remember the Enumerator? The block is going to be suspended, and the next time you call .resume, the argument to resume becomes the new data_to_write.

deferred_writes = Fiber.new do |data_to_write|
  loop do
    $stderr.puts "Received #{data_to_write} to work with"
    data_to_write = Fiber.yield
  end
end
# => #<Fiber:0x007f9f531783e8>
deferred_writes.resume("Hello") #=> Received Hello to work with
deferred_writes.resume("Goodbye") #=> Received Goodbye to work with

So, within the Fiber, the code flow is started on the first call to Fiber#resume, suspended at the first call to Fiber.yield, and then continued on subsequent calls to Fiber#resume, with the return value of Fiber.yield being the arguments to resume. The code continues running from the point where Fiber.yield was last called.

This is a bit of a quirk of Fibers in that the initial arguments to the fiber will be passed to you as the block arguments, not via the return value of Fiber.yield.

With that in mind, we know that by passing a special argument to resume, we can decide within the Fiber whether we should stop or not. Let's try that:

deferred_writes = Fiber.new do |data_to_write|
  loop do
    $stderr.puts "Received #{data_to_write} to work with"
    break if data_to_write == :terminate # Break out of the loop, or...
    write_to_output(data_to_write)       # ...write to the output
    data_to_write = Fiber.yield          # suspend ourselves and wait for the next `resume`
  end
  # We end up here if we break out of the loop above. There is no Fiber.yield
  # statement anywhere, so the Fiber will terminate and become "dead".
end

deferred_writes.resume("Hello") #=> Received Hello to work with
deferred_writes.resume("Goodbye") #=> Received Goodbye to work with
deferred_writes.resume(:terminate)
deferred_writes.resume("Some more data after close") # FiberError: dead fiber called

There are a number of situations where these facilities can be very useful. Since a Fiber contains a suspended block of code that can be manually resumed, Fibers can be used for implementing event reactors and for dealing with concurrent operations within a single thread. They are lightweight, so you can implement a server using Fibers by assigning a single client to a single Fiber and switching between these Fiber objects as necessary.

client_fiber = Fiber.new do |socket|
   loop do
     received_from_client = socket.read_nonblock(10)
     sent_to_client = socket.write_nonblock("OK")
     Fiber.yield # Return control back to the caller and wait for it to call 'resume' on us
   end
end

client_fibers << client_fiber

# and then in your main webserver loop
client_fibers.each do |client_fiber|
  client_fiber.resume # Receive data from the client if any, and send it an OK
end

Ruby has an additional standard library called fiber which allows you to explicitly transfer control from one fiber to another, which can be a bonus facility for these uses.

Controlling Data Emission Rates

Another great use for fibers and enumerators can arise when you want to be able to control the rate at which a Ruby block emits data. For example, in zip_tricks we support the following block use as the primary way of using the library:

ZipTricks::Streamer.open(output_io) do |z|
  z.write_deflated_file("big.csv") do |destination|
   columns.each do |col|
     destination << column
   end
  end
end

We therefore allow "push" control on the part of the code that creates the ZIP archive, and it is impossible to control how much data it outputs and how often. If we want to write our ZIP in chunks of, say, 5 MB—which would be a limitation on AWS S3 object storage—we would have to create a custom output_io object which would somehow "refuse" to accept << method calls when the segment needs to be split off into an S3 multipart part. We can, however, invert the control and make it "pull". We will still use the same block for writing our big CSV file, but we will be resuming and halting it based on the output it provides. We therefore make the following use possible:

output_enum = ZipTricks::Streamer.output_enum do |z|
  z.write_deflated_file("big.csv") do |destination|
   columns.each do |col|
     destination << column
   end
  end
end

# At this point nothing has been generated or written yet
enum = output_enum.each # Create an Enumerator
bin_str = enum.next # Let the block generate some binary data and then suspend it
output.write(bin_str) # Our block is suspended and waiting for the next invocation of `next`

This allows us to control at which rate our ZIP file generator emits data.

Enumerator and Fiber are, therefore, a control flow mechanism for turning "push" blocks into "pull" objects that accept method calls.

There is only one pitfall with Fibers and Enumerators—if you have something like ensure in your block, or something that needs to be done after the block completes, it is now up to the caller to call you enough times. In a way, it is comparable to the constraints you have when using Promises in JavaScript.

Conclusion

This concludes our look into flow-controlled enumerables in Ruby. Along the way, Julik shone light on the similarities and differences between the Enumerable and Fiber classes, and dove into examples where caller determined the flow of data. We’ve also learned about Fiber’s additional magic to allow passing arguments on each block reentry. Happy flow-controlling!

To get a steady dose of magic, subscribe to Ruby Magic and we'll deliver our monthly edition straight to your inbox.

Guest Author Julik Tarkhanov is a VFX artist gone rogue and Ruby. By day and night he toots the horn at the WeTransfer OSS repos like ZipTricks and ImageVise