In Progress
Unit 1, Lesson 1
In Progress

Crash Logger

Even the best programs crash. In this episode, you’ll learn how to build a custom Ruby crash logger which saves all the debug information most relevant to your application.

Video transcript & code

Programs crash. It's a fact of life. And when they do, we want to know why.

Ruby interpreters try to help out with this. When a program is brought down by an unhandled exception, the Ruby runtime dumps an exception backtrace before exiting.

def buggy_method(buggy_weight, horse_count=ENV["HORSE_COUNT"].to_i)
  buggy_weight / horse_count # ~> ZeroDivisionError: divided by 0
end

buggy_method(480)

# ~> ZeroDivisionError
# ~> divided by 0
# ~>
# ~> xmptmp-in43008ug.rb:2:in `/'
# ~> xmptmp-in43008ug.rb:2:in `buggy_method'
# ~> xmptmp-in43008ug.rb:5:in `<main>'

This is useful, but sometimes it doesn't capture all the information we'd like in order to diagnose the problem.

For instance, what if we wanted to save a snapshot of the program's environment variables at the time of the crash?

For a simple script, we might wrap the whole program in a begin…end block. Then we could intercept any Exception . (We explicitly specify the base Exception class here, because by default Ruby only rescues the RuntimeError subcategory of exceptions).

In the rescue block, we capture the current environment variable table as a hash, and then pretty-print it .

Finally, we re-raise the current exception in order to engage Ruby's usual backtrace-printing behavior.

When we run this, we can see that the environment is printed before the backtrace.

begin

  def buggy_method(buggy_weight, horse_count=ENV["HORSE_COUNT"].to_i)
    buggy_weight / horse_count # ~> ZeroDivisionError: divided by 0
  end

  buggy_method(480)

rescue Exception
  env = ENV.to_h
  require "pp"
  puts "--- Crash Environment ---"
  pp env
  raise
end

# >> --- Crash Environment ---
# >> {"HOME"=>"C:\\Users\\avdi_000\\AppData\\Roaming",
# >>  "LANG"=>"ENU",
# >>  "OS"=>"Windows_NT",
# ...

# ~> ZeroDivisionError
# ~> divided by 0
# ~>
# ~> xmptmp-in4300-wu.rb:4:in `/'
# ~> xmptmp-in4300-wu.rb:4:in `buggy_method'
# ~> xmptmp-in4300-wu.rb:7:in `<main>'

This is all well and good for a tiny one-off script. But in larger applications, there are a few problems with this approach.

First, it might not be sufficient to print the crash information to standard output. We might want to save crash logs in a more persistent format, such as in the form of files on disk.

And second, in larger applications, it may not be feasible to wrap the entire program in a begin…rescue…end block. If we're writing an app based on a framework like Ruby on Rails, we may not even control the code that starts and stops our application.

Fortunately, as we saw recently in Episode #488, Ruby gives us a way to register a "handler" that will be triggered whenever the program exits.

By calling at_exit with a block, we arrange for that code to be executed when the program shuts down.

at_exit do
  puts "Rearranging deck chairs"
end

puts "Welcome aboard"

# >> Hello!
# >> Bye bye!

And as we saw in that episode, this includes both ordinary benign exits and program terminations caused by unhandled exceptions.

at_exit do
  puts "Rearranging deck chairs"
end

fail "Abandon ship!" # ~> RuntimeError: Abandon ship!

# >> Rearranging deck chairs

# ~> RuntimeError
# ~> Abandon ship!
# ~>
# ~> xmptmp-in15504_7e.rb:5:in `<main>'

Knowing this, we can proceed to implement one of my favorite uses for at_exit: a crash logger.

We'll start by writing a method to dump a crash log file to the disk. We make it take an argument, the exception which has caused the crash. We'll have this argument default to the current active exception, using the special error info variable.

We want the crash dumps to have meaningful names. So we'll collect a few bits of information:

  • The current program's name, using the $0 special variable.
  • The process ID, using the $$ special variable.
  • And a timestamp, which we get by sending the strftime message to the current time.

We put these together into a filename. Now, let's collect some error information. We instantiate a hash to temporarily hold the error info as we collect it.

First off, we want to include the exception itself.

Then, we want the stack trace leading up to the error.

Finally, we'll capture the current process environment as a hash.

We'll dump all of these in YAML format to the filename we constructed earlier.

Finally, we'll return the name of the file that was created.

Now that we have a crash logging method, we need a way to trigger it when the program crashes.

For that, we set up an at_exit block.

Now, we only want to invoke the crash logging logic if the program is actually crashing. So we need to detect the circumstances under which the exit handler is being triggered.

So we add a conditional.

In order to see if the exit is being triggered by an unhandled exception, we switch on the state of the error info, or $! variable.

Initially we might think that checking if this variable is non-nil is all we have to do - if there's a currently active exception, that means the program must be crashing, right? But if you watched Episode #489, you know that there's a complication. Ruby implements the standard Kernel exit method by raising a SystemExit exception.

begin
  exit
rescue Exception => e
  e  # => #<SystemExit: exit>
end

This is how Ruby arranges to have ensure blocks perform all their necessary clean-up work even when the program exits early.

begin
  exit
ensure
  puts "Cleaning up..."
end
# >> Cleaning up...

So we can't just trigger our crash info collection for any exception.

Instead, we'll first filter out the nil case and the SystemExit case.

Then, if we get past those checks, we'll invoke our crash logging method.

Let's add one more convenience. Instead of just silently dumping a crash log to the disk, let's let anyone watching the program's output know about it.

To do that, we'll capture the generated crash log filename.

And then we'll output a message to the standard error stream, noting the existence of the crash log file.

require "yaml"

module CrashLogger
  def self.log_crash_info(error=$!)
    program_name = $0
    process_id   = $$
    timestamp    = Time.now.utc.strftime("%Y%m%d-%H%M%S")

    filename = "crash-#{program_name}-#{process_id}-#{timestamp}.yml"

    error_info = {}
    error_info["error"]       = error
    error_info["stacktrace"]  = error.backtrace
    error_info["environment"] = ENV.to_h

    File.write(filename, error_info.to_yaml)
    filename
  end
end

at_exit do
  unless $!.nil? || $!.is_a?(SystemExit)
    filename = CrashLogger.log_crash_info
    $stderr.puts "A crash log has been saved to: #{filename}"
  end
end

We'll save this code to a file.

Now let's test out our crash logger. We'll require it, and then run our buggy method from before.

This time we can see that in addition to the stack trace Ruby normally prints, we also have a message about a crash log being saved.

require "./crash_logger"

def buggy_method(buggy_weight, horse_count=ENV["HORSE_COUNT"].to_i)
  buggy_weight / horse_count # ~> ZeroDivisionError: divided by 0
end

buggy_method(480, 4)

# !> A crash log has been saved to: crash-xmptmp-in4300Ilt.rb-17388-20170609-131135.yml

# ~> ZeroDivisionError
# ~> divided by 0
# ~>
# ~> xmptmp-in4300Ilt.rb:4:in `/'
# ~> xmptmp-in4300Ilt.rb:4:in `buggy_method'
# ~> xmptmp-in4300Ilt.rb:7:in `<main>'

When we examine that file, we can see a human-readable YAML dump of the error itself, the stack trace, and the environment at the time of the crash.

Going back to our application code, I just want to draw attention one more time to the fact that all we had to do to enable our crash logger was to require the file. We didn't have to wrap all of our code in any kind of error-handling block. Our crash logger library is re-usable, and we can include it in all kids of applications, including ones built on a framework like Ruby on Rails.

Let's return one last time to the implementation of our crash-logging method.

Saving the process environment is just one example of the kinds of information we might want to save in a crash log. You can probably think of other types of diagnostic information that you'd find useful for your own applications.

One other thing I wanted to note before we finish, is that we've made use of a lot of Ruby's Perl-style special variables, like $0 for the current process name, $$ for the process ID, and of course $! for the current active exception. We'll talk about a way to make these variables more readable in an upcoming episode.

And there you have it: a template for an application crash logger which you can customize and build on for your own purposes. Happy hacking!

Responses