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
endmetric = 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
endclass 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?