urgetopunt technologies

Negative Test Suite Runtimes, or Don’t Forget to Call Timecop.return

tl;dr When using Timecop, always remember to turn it off at the end of the test.

I post this in the hopes that I’m not the only one to make this mistake and someone else might actually benefit from my stupidity.

It’s a sad truth, but in my experience, when googling, googling again and googling some more for a solution to a problem turns up nary a post from someone having the same problem, it’s usually because PEBKAC (I’m an idiot). For several days I’ve been noticing in frustration that the RSpec suite on one of my applications was periodically reporting negative runtimes, e.g.,

Finished in -537150.87202 seconds
329 examples, 0 failures

This consistently happened when running the entire test suite, but seemed sporadic when running a subset of the test suite. Adding to my confusion, at just about the same time that this problem appeared I had upgraded to RSpec 2.8 which fixed an issue that popped up when using Spork. I grudgingly pushed the matter to the back of my mind since, with the test suite running sufficiently fast, there were higher priority tasks. But today I found myself specfically wanting to benchmark the test suite, and these negative runtimes just wouldn’t do. So I poked around deeper.

I generated a fresh Rails application using the same template I’d used to generate the offending application. Running the new application’s nigh empty test suite reported accurate (positive) runtimes, so I started looking for additions/modifications made to spec/spec_helper.rb to see where things diverged. Nothing seemed significant. I then checked Gemfile to see what gems had been added to the offending application. Timecop! Of course, if something was going to interfere with runtime calculations, freezing Time would probably do it. I grepped for Timecop in my spec files and found it in use in only one, but damningly, it was mentioned only once. I was calling Timecop.freeze from a before block, but I was not restoring Time by calling Timecop.return from a corresponding after block.

face.send(:palm)

I added the missing after block. Runtime reports were accurate once again. Unicorns! Rainbows! Chocolate milk!

As an aside, if you use RSpec and Spork, and had found yourself adding the following to your spec_helper.rb:

Spork.each_run do
  $rspec_start_time = Time.now
 end

You can remove that kludge after you upgrade to RSpec 2.8. Yay!

Factory Girl and Guard

I’ve kept factory_girl in my testing toolkit for some time now, and recently, I started using guard to run my tests automatically as I make changes. I wanted guard to run the appropriate model, controller and request specs when I change a particular factory. Guard doesn’t know what to do with factory files by default, so I added the following to my Guardfile:

By convention, my factories are named after the plural form of the model name, and the files live in spec/factories, so, for example, my User factories are defined in spec/factories/users.rb. I require active_support/inflector at the top of the Guardfile because I need access to String#singularize to convert the plural factory name (also used in the name of controller and request specs) into the singular model name. Then I call #watch with the pattern matching the factory files and use the name of the factory to build the array of specs that need to be run.

SSL Gotcha with Puppet and Ruby 1.9.2

I’ve been preparing to build up a new Puppet installation, and as I’ve been deploying applications running on Ruby 1.9.2 lately, I thought it would be preferable to run Puppet under Ruby 1.9.2 as well. I’ve only begun the work, and I did run into a strange gotcha with SSL, but I seem to have gotten past it.

My test installation consists of two identical Debian 6.0 virtual machines running inside VirtualBox on a Mac. I started with a bare minimal install and ensured name resolution was working properly on both machines. The puppet master returns its hostname as “puppet.local”; the client returns its hostname as “client.local”. There are entries for both of these hostnames in /etc/hosts on each virtual machine, and they are able to ping each other by name.

Next, I ran the following bootstrap script on each machine to install Ruby 1.9.2-p290 and the puppet gem.

#!/bin/bash

set -e

PATH=/sbin:/usr/sbin:/usr/local/bin:/bin:/usr/bin

useradd -M -r puppet
apt-get update
apt-get dist-upgrade
apt-get install -y build-essential zlib1g-dev libssl-dev libreadline-dev git-core curl ntp

git clone git://github.com/sstephenson/ruby-build.git /root/ruby-build
cd /root/ruby-build
sh ./install.sh

ruby-build 1.9.2-p290 /usr/local
gem install puppet --no-ri --no-rdoc

Then, on the machine designated to become the puppet master, I performed the following to bring the puppet master daemon up.

# puppet master --genconfig > /etc/puppet.conf
# mkdir -p /etc/puppet/manifests
# touch /etc/puppet/manifests/site.pp
# puppet master --no-daemonize --verbose --debug

Finally I ran the puppet agent on the client expecting the client to send a certificate signing request to the puppet master which I could then sign to authorize the client.

# puppet agent --no-daemonize --verbose --debug --onetime

Instead, the puppet agent bailed out with the following error message:

err: Could not request certificate: SSL_connect returned=1 errno=0 state=SSLv3 read server certificate B: certificate verify failed.  This is often because the time is out of sync on the server or client
Exiting; failed to retrieve certificate and waitforcert is disabled

Gah! The puppet master never even logged the connection — the agent aborted immediately because it was unable to verify the certificate authority provided by the puppet master. The error message suggests clocks being out of sync is a common cause of such problems, but I verified the clocks on both machines were perfectly in sync. In fact, the bootstrap script installs ntp for just this purpose.

(The clock synchronization problem stems from the fact that the puppet master’s CA certificate is only valid between two dates determined with the certificate is generated. If the clock on the client is, for whatever reason, set ahead of the certificate’s expiration date or behind the certificate’s inaugration date, it will reject the certificate. You can check the validity dates by running the following command on the puppet master:

# openssl x509 -text -noout -in /etc/puppet/ssl/certs/ca.pem | grep -A2 Validity

In my case, the current time on the puppet client was well within the valid date range of the puppet master’s CA.)

It turns out, this is a known issue with the way Ruby 1.9.2 handles SSL certificate validations. One option is to downgrade the puppet client to Ruby 1.8.7. The puppet agent works fine, but this is not a desirable solution since I started the project with the goal of deploying application servers running Ruby 1.9.2. Another possibility is to install Ruby 1.8.7, initialize the puppet client and then upgrade to Ruby 1.9.2 after the initial SSL verification has taken place and /etc/puppet/ssl on the client has been populated. That’s reasonably easy to build into the bootstrap script, but it’s hardly desirable. And I suspect I’d just run into the same problem again if I had to regenerate the puppet master’s CA certificate for any reason.

Wouldn’t it be nice if someone had already figured out how to enable Ruby 1.9.2 to accept the puppet master’s CA certificate? Someone has. It turns out, all Ruby 1.9.2 needs is to find a copy of the puppet master CA certificate (or a symlink to it) in OpenSSL’s certificates directory with a filename correspoding to a hash of the certificate subject.

The first step is to copy /etc/puppet/ssl/certs/ca.pem from the puppet master to the puppet client. (This is one of those tasks that should be easily added to the bootstrap script I will use to bring up new puppet clients.) Next, a symlink to that file needs to be added to the OpenSSL certificates directory. This is the certs directory which resides underneath the directory returned by running openssl version -d. On Debian this is /usr/lib/ssl/certs (which is really just a symlink to /etc/ssl/certs). Finally, create the symlink to ca.pem using OpenSSL to calculate the hash value for the symlink name.

# ln -s /etc/puppet/ssl/certs/ca.pem /usr/lib/ssl/certs/$(openssl x509 -hash -noout -in /etc/puppet/ssl/certs/ca.pem).0

After performing these steps, running puppet agent for the first time (or again, but after /etc/puppet has been removed on the client) under Ruby 1.9.2 works like a charm. This is as far as I’ve gotten with this project so far. I don’t know if there are any more gotchas with running Puppet under Ruby 1.9.2, but this one stumped me for long enough that I thought it was worth sharing a solution.