Ruby, Serialization, and Enumeration

In which a curious backtrace uncovers scandalous truths about ActiveSupport and Ruby’s IO object.

Written by Xavier Shay.

Heads up, we’ve moved! If you’d like to continue keeping up with the latest technical content from Square please visit us at our new home https://developer.squareup.com/blog

We came across an interesting Ruby puzzler the other day. Code that had been working fine had started failing during serialization with a scary looking backtrace from within activesupport:

json.rb:128:in `each': not opened for reading (IOError)
  from /gems/activesupport-4.1.1/lib/active_support/core_ext/object/json.rb:128:in `to_a'
  from /gems/activesupport-4.1.1/lib/active_support/core_ext/object/json.rb:128:in `as_json'
  from /gems/activesupport-4.1.1/lib/active_support/core_ext/object/json.rb:159:in `block in as_json'
  from /gems/activesupport-4.1.1/lib/active_support/core_ext/object/json.rb:159:in `each'
  from /gems/activesupport-4.1.1/lib/active_support/core_ext/object/json.rb:159:in `map'
  from /gems/activesupport-4.1.1/lib/active_support/core_ext/object/json.rb:159:in `as_json'
  from /gems/activesupport-4.1.1/lib/active_support/core_ext/object/json.rb:50:in `as_json'
  from /gems/activesupport-4.1.1/lib/active_support/core_ext/object/json.rb:159:in `block in as_json'
  from /gems/activesupport-4.1.1/lib/active_support/core_ext/object/json.rb:159:in `each'
  from /gems/activesupport-4.1.1/lib/active_support/core_ext/object/json.rb:159:in `map'
  from /gems/activesupport-4.1.1/lib/active_support/core_ext/object/json.rb:159:in `as_json'
  from /gems/activesupport-4.1.1/lib/active_support/core_ext/object/json.rb:50:in `as_json'
  from /gems/activesupport-4.1.1/lib/active_support/core_ext/object/json.rb:159:in `block in as_json'
  from /gems/activesupport-4.1.1/lib/active_support/core_ext/object/json.rb:159:in `each'
  from /gems/activesupport-4.1.1/lib/active_support/core_ext/object/json.rb:159:in `map'
  from /gems/activesupport-4.1.1/lib/active_support/core_ext/object/json.rb:159:in `as_json'
  from /gems/activesupport-4.1.1/lib/active_support/core_ext/object/json.rb:50:in `as_json'
  from /gems/activesupport-4.1.1/lib/active_support/json/encoding.rb:34:in `encode'
  from /gems/activesupport-4.1.1/lib/active_support/json/encoding.rb:21:in `encode'
  from /gems/activesupport-4.1.1/lib/active_support/core_ext/object/json.rb:37:in `to_json_with_active_support_encoder'
  from test.rb:15:in `<main>'

The issue was isolated to a particular change to a class that was being serialized inside a larger data structure (which I’ve further simplified):

require 'active_support/all'
class Metric
  attr_reader :timestamp, :value
  def initialize(timestamp, value)
    @timestamp = timestamp
    @value     = value
    @logger    = Logger.new($stdout)
  end
end
metric = Metric.new(Time.now, 5)
puts metric.to_json

The addition of the @logger variable was causing the problem, even though it was never used! Commenting out that line made the problem go away. This is certainly non-intuitive. What is going on? Let’s find out.

One of Ruby’s best features is the transparency of its libraries. We have the full path to the source of the exception right there in the backtrace. Opening up /gems/activesupport-4.1.1/lib/active_support/core_ext/object/json.rbin your favourite editor (obviously your path will be different) gives a major hint: this file is monkey-patching a number of core classes to support serialization.

module Enumerable
  def as_json(options = nil) #:nodoc:
    # ...
  end
end
class Hash
  def as_json(options = nil) #:nodoc:
    # ...
  end
end
# ... and many more!

Looking at the Metric code above, how did it know how to serialize the object to JSON in the first place? Sure enough, elsewhere in json.rb (which also appears in our stack trace):

class Object
  def as_json(options = nil) #:nodoc:
    if respond_to?(:to_hash)
      to_hash.as_json(options)
    else
      instance_values.as_json(options)
    end
  end
end

Metric does not implement to_hash, so all of its instance variables are being included in the JSON representation. That explains why the unused @logger variable was the difference between success and failure. An easy fix then is to implement to_hash. Even if @logger was serializing correctly, it is unwanted in the JSON output.

However that still doesn’t explain the opaque error: not opened for reading (IOError). The quickest way to track that down, since we already have json.rbopen, is to add some quick debugging output before the line that failed:

module Enumerable
  def as_json(options = nil) #:nodoc:
    puts self.inspect
    to_a.as_json(options)
  end
end

This is why library transparency in Ruby is particularly amazing: you can also modify them in-place and see the results immediately!

In this instance a single line is output:

#<IO:<STDOUT>>

That explains it. For better or worse, IO objects in Ruby are enumerable. The semantics here are questionable: to_a is indeed part of the Enumerable interface, but making an IO into an array doesn’t really make sense. And having each chunk on line breaks is somewhat arbitrary anyway.

This mismatch has historically dogged Enumerable and uses of that interface. Take this gem from rspec-expectations:

if String.ancestors.include?(Enumerable) # 1.8.7
  # Strings are not enumerable on 1.9, and on 1.8 they are an infinitely
  # nested enumerable: since ruby lacks a character class, it yields
  # 1-character strings, which are themselves enumerable, composed of a
  # a single 1-character string, which is an enumerable, etc.
  #
  # @api private
  def enumerable?(item)
    return false if String === item
    Enumerable === item
  end
else
  # @api private
  def enumerable?(item)
    Enumerable === item
  end
end

The comment says it all really! Funnily enough, the caller of this method has to special case IO as well:

def surface_descriptions_in(item)
  if Matchers.is_a_describable_matcher?(item)
    DescribableItem.new(item)
  elsif Hash === item
    Hash[ surface_descriptions_in(item.to_a) ]
  elsif enumerable?(item)
    begin
      item.map { |subitem| surface_descriptions_in(subitem) }
    rescue IOError # STDOUT is enumerable but `map` raises an error
      item.inspect
    end
  else
    item
  end
end

String is no longer Enumerable since Ruby 1.9. Should IO follow in its footsteps?

Xavier Shay (@xshay) | Twitter