Cameron Dutro on March 12, 2015
Have you ever cracked open a misbehaving gem in the hopes of tracking down a bug in your app? If so, then you’re a code reader. Have you ever had to modify a piece of code you didn’t write? Surprise! You’re a code reader too. In fact, chances are you’re a code reader even if you’re looking back over your own code. At Lumos Labs, we’ve formed a code reading club to celebrate the code we’ve read and tell our co-workers what we learned in the process. This post is part of what will hopefully become a series of posts about what we discuss during our meetings. In this first post, I’ll talk about what it means to “read” code, and then dive into the Timecop gem, a library that’s capable of freezing and travelling through time in Ruby tests.
What does it mean to “read” code?
If there’s one message you should take away from this blog post, it’s that reading code is not like reading literature. Code reading is the process of code exploration. Generally speaking you won’t go open up one of your app’s dependencies and read it just for fun - you’ll need a goal. In this post, a bug in Timecop caused one of our scripts to fail, so I needed to read Timecop’s code to find and fix the bug. Other examples of goals might be, “I can’t figure out how to do an outer join in Rails,” or, “Why isn’t this Backbone callback getting fired?”
How I read code
Personally, I tend to read code the same way each time:
1) Examine the file structure
How are the files organized? How do components (classes, modules, etc) get loaded?
2) Isolate components
Where does the core functionality live? Which components look like they could help me find answers? Which components are just boilerplate?
3) Identify issue site
Generally, what part of the code looks like it does the thing I care about?
4) Trace method calls
What chain of method calls leads to the issue site? How can I interrupt, hook, or augment this chain to get what I want?
5) Introduce modification
You may want to temporarily add a monkey-patch to your project so you can keep working. However, most modifications should eventually be introduced in the form of a pull request.
Didn’t work? Try again.
What’s the most important quality of a code reader? Tenacity!
The Problem™
Timecop is a really cool library. It allows you to easily manipulate time in your Ruby tests. Check this out:
1
2
3
4
5
6
7
joe.mortgage_due? # false
Timecop.freeze(Date.today + 30) do
joe.mortgage_due? # true
end
joe.mortgage_due? # false
Pretty cool, right? Timecop also has a #return method that can temporarily restore the current system time within the given block:
1
2
3
4
5
6
7
8
9
10
11
12
13
joe.mortgage_due? # false
Timecop.freeze(Date.today + 30) do
joe.mortgage_due? # true
Timecop.return do
joe.mortgage_due? # false
end
joe.mortgage_due? # true
end
joe.mortgage_due? # false
Even cooler. However, a problem arises if an error is raised inside #return:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
joe.mortgage_due? # false
Timecop.freeze(Date.today + 30) do
joe.mortgage_due? # true
begin
Timecop.return do
joe.mortgage_due? # false
raise 'foo!'
end
rescue
end
joe.mortgage_due? # false
end
joe.mortgage_due? # false
Joe’s mortgage should still be due on line 14, since that line is still running in the context of the freeze. Something’s not right here.
Examining the file structure
The first thing I did was to look at Timecop’s file structure.
Most of these files are just gem boilerplate - the meat lies within lib.
The only file in here is lib/timecop.rb, which is responsible for loading the rest of the library, i.e. all the files in lib/timecop/. This technique is very standard, and you’ll see it in most gems. What we’re looking for must be another level deeper.
Ah, there we go! We’ve found where all the actual Timecop functionality lives, which brings us to…
Isolating components
In lib/timecop/ there are three main components:
time_stack_item.rb: Defines the TimeStackItem class. The comment above the definition of TimeStackItem says:
“A data class for carrying around ‘time movement’ objects. Makes it easy to keep track of the time movements on a simple stack.”
time_extensions.rb: Monkey-patches Date, Time, and DateTime.
timecop.rb: Defines the Timecop class which contains the .freeze and .return methods.
I’d say the definition of the .freeze method is a good place to start. Let’s take a look.
Tracing method calls
.freeze delegates to the .send_travel method, which looks like this:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
class Timecop
include Singleton
class << self
...
def freeze(*args, &block)
send_travel(:freeze, *args, &block)
end
private
def send_travel(mock_type, *args, &block)
val = instance.send(:travel, mock_type, *args, &block)
block_given? ? val : Time.now
end
...
end
end
It looks like Timecop makes use of the singleton design pattern, which is where that instance variable comes from on line 14. In case you’re not familiar with singletons, here’s what Wikipedia has to say:
“In software engineering, the singleton pattern is a design pattern that restricts the instantiation of a class to one object. This is useful when exactly one object is needed to coordinate actions across the system.”
Ok cool, so only one instance of the Timecop class can exist. Good to know, but not really getting us any closer to finding the bug. Let’s follow the method calls and examine the instance-level #travel method (we looked at the class-level one before):
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
class Timecop
...
private
def travel(mock_type, *args, &block) #:nodoc:
raise SafeModeException if Timecop.safe_mode? && !block_given?
stack_item = TimeStackItem.new(mock_type, *args)
stack_backup = @_stack.dup
@_stack << stack_item
if block_given?
begin
yield stack_item.time
ensure
@_stack.replace stack_backup
end
end
end
...
end
This code tells us that Timecop maintains a stack of TimeStackItems, which it uses to keep track of nested times. For example, if you called Timecop.freeze within another Timecop.freeze, two TimeStackItems would get pushed onto Timecop’s internal stack. The most recently pushed time is the current time. When the internal #freeze block ends, the last pushed item is popped off the stack and the time from the outer #freeze is restored (i.e. becomes the last pushed time).
Ok, so what have we learned so far?
We now know three major things about the Timecop gem:
1) The file structure is laid out like a standard Rubygem.
2) The user-facing “global” methods live in lib/timecop/timecop.rb.
3) Timecop uses a stack to nest calls to #freeze. It pushes instances of the TimeStackItem class when the block given to #freeze begins, and pops them off when the block ends.
Although we have learned a great deal about Timecop, we still haven’t found the source of the problem. Timecop#freeze looks pretty solid. The issue must reside in Timecop#return.
Tracing method calls (take 2)
Here’s the Timecop#return method. Pay particular attention to the yield on line 8:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
class Timecop
...
def return(&block)
current_stack = @_stack
current_baseline = @baseline
unmock!
yield
@_stack = current_stack
@baseline = current_baseline
end
def unmock! #:nodoc:
@baseline = nil
@_stack = []
end
...
end
What happens if an error gets raised when the method yields? Gotcha! The last two statements on lines 9 and 10 won’t get executed. Since lines 9 and 10 restore the stack, the time from the outer freeze won’t be restored, and the current time will remain the system time, as if our code is still running inside a Timecop#return block.
Now that we’ve successfully isolated the bug, it’s time to write a test (Timecop uses Minitest):
1
2
3
4
5
6
7
8
9
10
11
12
13
class TestTimecop < Minitest::Unit::TestCase
...
def test_exception_thrown_in_return_block_restores_previous_time
t = Time.local(2008, 10, 10, 10, 10, 10)
Timecop.freeze(t) do
Timecop.return { raise 'foobar' } rescue nil
assert_equal t, Time.now
end
end
...
end
As we expect, this test fails. Let’s go back and modify Timecop#return to make it pass.
Introducing the modification
Now that we know what’s wrong, it should be fairly straightforward to fix. All we need to do is add an ensure statement on line 9:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
class Timecop
...
def return(&block)
current_stack = @_stack
current_baseline = @baseline
unmock!
yield
ensure
@_stack = current_stack
@baseline = current_baseline
end
def unmock! #:nodoc:
@baseline = nil
@_stack = []
end
...
end
The ensure statement makes sure that, even if an error gets raised in the yield, the current time stack will be restored. Sure enough, with this modification in place, all the tests pass.
Wrapping up
In order to address the issue, we developed and validated a hypothesis given a few inputs:
1) Given: If an error is raised in Timecop#return, the previous time stack doesn’t get reset.
2) Hypothesis: Any code running inside Timecop#freeze will experience an unexpected time state. Adding an ensure statement will cause Timecop to correctly restore the time stack on error.
3) Conclusion: The test we wrote validates our hypothesis.
Contributing back
Timecop is an open-source project that many Ruby developers use and benefit from, including us here at Lumos Labs. When I find bugs like this, I like to contribute a fix back to the project as a way of saying “Thanks” to the author and potentially helping other developers who might have run into the same issue. To that end, I created a pull request on the Timecop repo. Hopefully someone will find my fix useful, and I encourage all code readers to contribute bug fixes to their favorite open-source projects as well.
Happy code reading!