In Progress
Unit 1, Lesson 1
In Progress

Logs And Signals

Video transcript & code

Two topics we've been talking about a lot lately are logging, and signals. Well today we're going to bring those topics together, with a trick I learned from logging expert Tim Pease.

Supposing we have a program which periodically logs information. Normally, we don't want to see debug messages, so we'll set the log level to INFO. Just for funsies, let's plug in the colorizing log formatter we wrote in episode #359.

require "pastel"
require "logger"

pastel = Pastel.new
colors = {
  "FATAL" => pastel.red.bold.detach,
  "ERROR" => pastel.red.detach,
  "WARN"  => pastel.yellow.detach,
  "INFO"  => pastel.green.detach,
  "DEBUG" => pastel.white.detach,
}
color_formatter = ->(severity, datetime, progname, message) {
  colorizer = $stdout.tty? ? colors[severity] : ->(s){s}
  "#{colorizer.(severity)}: #{message}\n"
}

logger = Logger.new($stderr)
logger.level = Logger::INFO
logger.formatter = color_formatter

loop do
  sleep 0.5
  logger.info "nureek"
  sleep 0.5
  logger.info "retut"
  sleep 0.5
  logger.debug "squrlookal"
  sleep 0.5
  logger.info "hanunga"
end

If we run this program, it ticks happily along emitting status updates.

$ ruby starbug.rb
INFO: nureek
INFO: retut
INFO: hanunga
INFO: nureek
INFO: retut

But what if things start to go wrong, and we decide we need to see debug output? In episode #340, we learned how to control log level using an environment variable. We could set the same thing up here.

But what if this is a program that takes a while to restart? What if we need to see debug output from a production server where we don't want to interrupt service just to switch logging levels? Or, what if we're trying to debug a scenario which only occurs after the program has been running for several hours?

In these cases, we'd like to have a way to switch logging levels on the fly, without restarting the server.

From episodes #353 and #354, we know a simple way to notify a running process of some event. We can send it a signal. Let's set up a signal handler using #trap.

This immediately begs a question: what signal should we trap? Most UNIX signals, like SIGINT or SIGTERM already have specific semantics associated with them, which we don't want to override.

But there are two special signals which are deliberately left open for application-specific interpretation. They are SIGUSR1 and SIGUSR2. Let's make SIGUSR1 our verbosity-toggling signal.

In the signal handler, we'll toggle the current state of the log level. If it is INFO we'll switch to DEBUG, and if it's DEBUG we'll switch back to INFO.

trap("USR1") do
  if logger.level == Logger::INFO
    logger.level = Logger::DEBUG
  else
    logger.level = Logger::INFO
  end
end

One bit of information we'll need if we want to send signals to this process is the process ID. We'll add that information to our log formatter, using the Ruby special variable $$.

color_formatter = ->(severity, datetime, progname, message) {
  colorizer = $stdout.tty? ? colors[severity] : ->(s){s}
  "(#{$$}) #{colorizer.(severity)}: #{message}\n"
}

 

When we run our updated program, we can see the PID information in the log lines.

$ ruby starbug2.rb
(5782) INFO: nureek
(5782) INFO: retut
(5782) INFO: hanunga
(5782) INFO: nureek

We can use this information to issue a USR1 signal to the process.

$ kill -USR1 5782

…after which, we can see the debug log lines start to appear.

(5782) DEBUG: squrlookal
(5782) INFO: hanunga
(5782) INFO: nureek
(5782) INFO: retut
(5782) DEBUG: squrlookal
(5782) INFO: hanunga

If we issue the same signal again, the debug output goes away.

And that's all there is to it: now we can toggle log verbosity without restarting the program. Happy hacking!

Responses