In Progress
Unit 1, Lesson 21
In Progress

Controlling Log Level

Video transcript & code

In the previous episode, we learned some basics about Ruby's Logger class and the concept of "severity levels". Today I thought I'd show you the simplest way I know to configure logging at program runtime.

Here's a little program that checks the weather and tells me if I need to take an umbrella with me when I go outside. I don't want this program to hit the weather service every single time I run it, so I've arranged some very simple local caching. I've also sprinkled the program with some INFO-level logging to let me know about the state of the cache: did the program find a cached version of the requested weather report, how old was it, that sort of thing.

In addition to the INFO-level logging, there's also a whole bunch of DEBUG logging. Debug messages include things like full dumps of the data returned from the weather service. This level of detail is tremendously useful when I'm making changes to the program, but otherwise it's way too much information.

In order to limit the amount of of logging output, I've set the logger level to INFO. As we learned in the last episode, this means that the logger will only emit messages for the INFO level of severity and above.

require "json"
require "net/http"
require "logger"

log = Logger.new($stderr)
log.level = Logger::INFO

zipcode = ARGV[0] or abort "You must supply a ZIP code"

cache_timestamp = File.exist?(zipcode) && File.new(zipcode).mtime

log.debug "Cache timestamp is #{cache_timestamp}"

cache_age = if cache_timestamp
              Time.now - cache_timestamp
            else
              Float::INFINITY
            end
log.info "Cache is #{cache_age} seconds old"


raw_data = if cache_age > 60 * 60
             log.info "Fetching data from server"
             uri = URI("http://api.openweathermap.org/data/2.5/weather?zip=#{zipcode},us")
             body = Net::HTTP.get_response(uri).body
             log.debug "Raw weather data:"
             log.debug body
             log.info "Writing data to cache"
             IO.write(zipcode, body)
             body
           else
             log.info "Fetching data from cache"
             IO.read(zipcode)
           end
log.debug raw_data
data = JSON.parse(raw_data)
weather_id = data.fetch("weather").fetch(0).fetch("id").to_i
if (200...600).include?(weather_id)
  puts "Take an umbrella"
else
  puts "No umbrella needed"
end

Let's give this a whirl:

$ ruby umbrella.rb 37902
I, [2015-08-07T14:22:09.146687 #17610]  INFO -- : Cache is 1031.639662202 seconds old
I, [2015-08-07T14:22:09.146749 #17610]  INFO -- : Fetching data from cache
No umbrella needed

Of course, in a more production-ready program I'd be logging to a file rather than the standard error stream, but I'm keeping it simple for the sake of demonstration.

Now, let's say we want to switch this program over to showing the full logging output, including debug information. Right now, we have to change the code in order to make this happen. For a program we're working on locally this isn't too onerous, but it's still inconvenient. If this were a server-based program, changing the code just to change logging levels would be a serious hassle.

Let's make it easier to switch logging levels without modifying the program. I'm going to show you the simplest, most straightforward way I know of to do this.

Instead of a hardcoded log severity constant, we tell the Logger class to look up a constant contained within its namespace. But what constant name will we tell it to look up?

For that, we look in the ENV object, which contains a map of all the environment variables currently set. Inside ENV, we look up the LOG_LEVEL variable, using .fetch.

Why #fetch? Because, as we learned in episode #12, #fetch allows us to specify a fallback value if the key is missing. As our fallback value, we specify the string ="INFO"=. We use a string here because remember, the result is going to be used as an argument to .const_get, which is expecting a string.

And that's it. We're done. Now let's try this out.

require "json"
require "net/http"
require "logger"

log = Logger.new($stderr)
log.level = Logger.const_get(ENV.fetch("LOG_LEVEL", "INFO"))

zipcode = ARGV[0] or abort "You must supply a ZIP code"

cache_timestamp = File.exist?(zipcode) && File.new(zipcode).mtime

log.debug "Cache timestamp is #{cache_timestamp}"

cache_age = if cache_timestamp
              Time.now - cache_timestamp
            else
              Float::INFINITY
            end
log.info "Cache is #{cache_age} seconds old"


raw_data = if cache_age > 60 * 60
             log.info "Fetching data from server"
             uri = URI("http://api.openweathermap.org/data/2.5/weather?zip=#{zipcode},us")
             body = Net::HTTP.get_response(uri).body
             log.debug "Raw weather data:"
             log.debug body
             log.info "Writing data to cache"
             IO.write(zipcode, body)
             body
           else
             log.info "Fetching data from cache"
             IO.read(zipcode)
           end
log.debug raw_data
data = JSON.parse(raw_data)
weather_id = data.fetch("weather").fetch(0).fetch("id").to_i
if (200...600).include?(weather_id)
  puts "Take an umbrella"
else
  puts "No umbrella needed"
end

Running the program as we did before, we see the same info-level output.

$ ruby umbrella2.rb 37902
I, [2015-08-07T14:28:04.591278 #17704]  INFO -- : Cache is 1387.084253132 seconds old
I, [2015-08-07T14:28:04.591348 #17704]  INFO -- : Fetching data from cache
No umbrella needed

But if we set the LOG_LEVEL environment variable to DEBUG and run the program again, we get a bunch more output!

$ LOG_LEVEL=DEBUG ruby umbrella2.rb 37902
D, [2015-08-07T14:28:16.229967 #17707] DEBUG -- : Cache timestamp is 2015-08-07 14:04:57 -0400
I, [2015-08-07T14:28:16.230039 #17707]  INFO -- : Cache is 1398.723014921 seconds old
I, [2015-08-07T14:28:16.230072 #17707]  INFO -- : Fetching data from cache
D, [2015-08-07T14:28:16.230120 #17707] DEBUG -- : {"coord":{"lon":-83.92,"lat":35.96},"weather":[{"id":804,"main":"Clouds","description":"overcast clouds","icon":"04d"}],"base":"cmc stations","main":{"temp":299.29,"pressure":1012,"humidity":65,"temp_min":298.71,"temp_max":300.15},"wind":{"speed":1.21,"deg":299.502},"clouds":{"all":90},"dt":1438969908,"sys":{"type":1,"id":2534,"message":0.0065,"country":"US","sunrise":1438944495,"sunset":1438994037},"id":4634946,"name":"Knoxville","cod":200}

No umbrella needed

On the other hand, if we set the log severity level to ERROR, we see no logging output at all, because there are no messages output at the ERROR level or higher.

$ LOG_LEVEL=ERROR ruby umbrella2.rb 37902
No umbrella needed

Using an environment variable to control logging levels is extraordinarily versatile. Most application hosting platforms make it easy to update environment variables and re-start the application using the new values. For example, for applications hosted on Heroku, we just have to issue the command:

$ heroku config:set LOG_LEVEL=DEBUG

…and Heroku will restart the applications dynos using the new environment variable value.

I'm not usually an advocate for adding code to an application before you have a need for it. But this one-liner is such a dead-simple way to make log levels configurable, that it's worth learning it by heart and throwing it in wherever you set up a logger. Someday you'll want to temporarily switch that logger into verbose mode, and you'll thank yourself for making it externally configurable. Happy hacking!

Responses