Tag Ruby

This is one of the stickers for the second edition of Rails Girls Vratsa which was held yesterday. Let's explore some of the bug proposals submitted by the Bulgarian QA group:

1. sad() == true is ugly
2. sad() is not very nice, better make it if(isSad())
3. use sadStop(), and even better - stopSad()
4. there is an extra space character in beAwesome( )
5. the last curly bracket needs to be on a new line

Lyudmil Latinov

My friend Lu describes what I would call style issues. The style he refers to is mostly Java oriented, especially with naming things. In Ruby we would probably go with sad? instead of isSad. Style is important and there are many tools to help us with that this will not cause a functional problem! While I'm at it let me say the curly brackets are not the problem either. They are not valid in Ruby this is a pseudo-code and they also fall in the style category.

The next interesting proposal comes from Tsveta Krasteva. She examines the possibility of sad() returning an object or nil instead of boolean value. Her first question was will the if statement still work, and the answer is yes. In Ruby everything is an object and every object can be compared to true and false. See Alan Skorkin's blog post on the subject.

Then Tsveta says the answer is to use sad().stop() with the warning that it may return nil. In this context the sad() method returns on object indicating that the person is feeling sad. If the method returns nil then the person is feeling OK.

class Csad
  def stop()
    print("stop\n");
  end
end

def sad()
  print("sad\n");
  Csad.new();
end

def beAwesome()
  print("beAwesome\n");
end

# notice == true was removed
if(sad())
  print("Yes, I am sad\n");
  sad.stop();
  beAwesome( );
end

While this is coming closer to a functioning solution something about it is bugging me. In the if statement the developer has typed more characters than required (== true). This sounds to me unlikely but is possible with less experienced developers. The other issue is that we are using an object (of class Csad) to represent an internal state in the system under test. There is one method to return the state (sad()) and another one to alter the state (Csad.stop()). The two methods don't operate on the same object! Not a very strong OOP design. On top of that we have to call the method twice, first time in the if statement, the second time in the body of the if statement, which may have unwanted side effects. It is best to assign the return value to some variable instead.

IMO if we are to use this OOP approach the code should look something like:

class Person
  def sad?()
  end

  def stopBeingSad()
  end

  def beAwesome()
  end
end

p = Person.new
if p.sad?
    p.stopBeingSad
    p.beAwesome
end

Let me return back to assuming we don't use classes here. The first obvious mistake is the space in sad stop(); first spotted by Peter Sabev*. His proposal, backed by others is to use sad.stop(). However they didn't use my hint asking what is the return value of sad() ?

If sad() returns boolean then we'll get undefined method 'stop' for true:TrueClass (NoMethodError)! Same thing if sad() returns nil, although we skip the if block in this case.

In Ruby we are allowed to skip parentheses when calling a method, like I've shown above. If we ignore this fact for a second, then sad?.stop() will mean execute the method named stop() which is a member of the sad? variable, which is of type method! Again, methods don't have an attribute named stop!

The last two paragraphs are the semantic/functional mistake I see in this code. The only way for it to work is to use an OOP variant which is further away from what the existing clues give us.

Note: The variant sad? stop() is syntactically correct. This means call the function sad? with parameter the result of calling the method stop(), which depending on the outer scope of this program may or may not be correct (e.g. stop is defined, sad? accepts optional parameters, sad? maintains global state).

Thanks for reading and happy testing!

Posted by Alexander Todorov on Mon 26 June 2017

There are comments.

Last week Anton asked me to take a look at one of his RSpec test suites. He was able to consistently reproduce a segfault which looked like this:

/home/atodorov/.rbenv/versions/2.3.2/lib/ruby/gems/2.3.0/gems/rspec-core-3.5.4/lib/rspec/core/runner.rb:113: [BUG] vm_call_cfunc - cfp consistency error
ruby 2.3.2p217 (2016-11-15 revision 56796) [x86_64-linux]

-- Control frame information -----------------------------------------------
c:0013 p:---- s:0048 e:000047 CFUNC  :map
c:0012 p:0011 s:0045 e:000044 BLOCK  /home/atodorov/.rbenv/versions/2.3.2/lib/ruby/gems/2.3.0/gems/rspec-core-3.5.4/lib/rspec/core/runner.rb:113
c:0011 p:0035 s:0043 e:000042 METHOD /home/atodorov/.rbenv/versions/2.3.2/lib/ruby/gems/2.3.0/gems/rspec-core-3.5.4/lib/rspec/core/configuration.rb:1835
c:0010 p:0011 s:0040 e:000039 BLOCK  /home/atodorov/.rbenv/versions/2.3.2/lib/ruby/gems/2.3.0/gems/rspec-core-3.5.4/lib/rspec/core/runner.rb:112
c:0009 p:0018 s:0037 e:000036 METHOD /home/atodorov/.rbenv/versions/2.3.2/lib/ruby/gems/2.3.0/gems/rspec-core-3.5.4/lib/rspec/core/reporter.rb:77
c:0008 p:0022 s:0033 e:000032 METHOD /home/atodorov/.rbenv/versions/2.3.2/lib/ruby/gems/2.3.0/gems/rspec-core-3.5.4/lib/rspec/core/runner.rb:111
c:0007 p:0025 s:0028 e:000027 METHOD /home/atodorov/.rbenv/versions/2.3.2/lib/ruby/gems/2.3.0/gems/rspec-core-3.5.4/lib/rspec/core/runner.rb:87
c:0006 p:0085 s:0023 e:000022 METHOD /home/atodorov/.rbenv/versions/2.3.2/lib/ruby/gems/2.3.0/gems/rspec-core-3.5.4/lib/rspec/core/runner.rb:71
c:0005 p:0026 s:0016 e:000015 METHOD /home/atodorov/.rbenv/versions/2.3.2/lib/ruby/gems/2.3.0/gems/rspec-core-3.5.4/lib/rspec/core/runner.rb:45
c:0004 p:0025 s:0012 e:000011 TOP    /home/atodorov/.rbenv/versions/2.3.2/lib/ruby/gems/2.3.0/gems/rspec-core-3.5.4/exe/rspec:4 [FINISH]
c:0003 p:---- s:0010 e:000009 CFUNC  :load
c:0002 p:0136 s:0006 E:001e10 EVAL   /home/atodorov/.rbenv/versions/2.3.2/bin/rspec:22 [FINISH]
c:0001 p:0000 s:0002 E:0000a0 (none) [FINISH]

Googling for vm_call_cfunc - cfp consistency error yields Ruby #10460. Comments on the bug and particularly this one point towards the error:

> Ruby is trying to be nice about reporting the error; but in the end,
> your code is still broken if it overflows stack.

Somewhere in the test suite was a piece of code that was overflowing the stack. It was somewhere along the lines of

describe '#active_client_for_user' do
  context 'matching an existing user' do
    it_behaves_like 'manager authentication' do
      include_examples 'active client for user with existing user'
    end
  end
end

Considering the examples in the bug I started looking for patterns where a variable was defined and later redefined, possibly circling back to the previous definition. Expanding the shared examples by hand transformed the code into

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13

describe '#active_client_for_user' do
  context 'matching an existing user' do
    let(:user) { create(:user, :manager) }
    let!(:api_user_authentication) { create(:user_authentication, user: user) }
    let(:user) { api_user_authentication.user }

    context 'with an `active_assigned_client`' do
      ... skip ...
    end

    ... skip ...
  end
end

Line 5. overrode line 3. When line 4. was executed first because of lazy execution and the call execution path became: 4-5-4-5-4-5 ... NOTE: I think we need a warning about that in RuboCop, see RuboCop #3769. The fix however is a no brainer:

-  let(:user) { create(:user, :manager) }
-  let!(:api_user_authentication) { create(:user_authentication, user: user) }
+  let(:manager) { create(:user, :manager) }
+  let!(:api_user_authentication) { create(:user_authentication, user: manager) }

Thanks for reading and happy testing.

Posted by Alexander Todorov on Sun 04 December 2016

There are comments.

Recently I've observed a strange behavior in one of the test suites I'm working with - a test which submits a web form appeared to fail at a rate between 10% and 30%. This immediately made me think there is some kind of race-condition but it turned out that Capybara's find().click method doesn't always fire the onClick event in the browser!

The test suite uses Capybara, Poltergeist and PhantomJS. The element we click on is an image, coupled to a hidden check-box underneath. When the image is clicked onClick is fired and the check-box is updated accordingly. In the failed cases the underlying check-box wasn't updated! Searching the web reveals a similar problem described by Alex Okolish so we've tried his solution:

div.find('.replacement', visible: true).trigger(:click)

How to Test

The failure behavior being somewhat flaky I've opted for running the test multiple times and see what happens when it fails. Initially I've executed the test in batches of 10 and 20 repetitions to get a feeling of how often does it fail before proceeding with debugging. Debugging was done by logging variables and state on the console and repeating multiple times. Once a possible solution was proposed we've run the tests in batches of 100 repetitions and counted how often they failed.

At the end, when Alex's solution was discovered we've repeated the testing around 1000 times just to make sure it works reliably. So far this has been working without issues!

I've spent around a week working on this together with a co-worker and we didn't really want to spend more time trying to figure out what was going wrong with our tools. Once we saw that trigger does the job we didn't continue debugging Capybara or PhantomJS.

Posted by Alexander Todorov on Tue 31 May 2016

There are comments.

As many others I've been trying to change Rails.application.config.consider_all_requests_local and Rails.application.config.action_dispatch.show_exceptions inside my RSpec tests in order to test custom error pages in a Rails app. However this doesn't work. My code looked like this

feature 'Exceptions' do
  before do
    Rails.application.config.action_dispatch.show_exceptions = true
    Rails.application.config.consider_all_requests_local = false
  end

This works only if I execute exceptions_spec.rb alone. However when something else executes before that it fails. The config values are correctly updated but that doesn't seem to have effect.

The answer and solution comes from Henrik N.

action_dispatch.show_exceptions gets copied and cached in Rails.application.env_config, so even if you change Rails.application.config.action_dispatch.show_exceptions in this before block the value isn't what you expect when it's used in ActionDispatch::DebugExceptions.

In fact DebugExceptions uses env['action_dispatch.show_exceptions']. The correct code should look like this

before do
  method = Rails.application.method(:env_config)
  expect(Rails.application).to receive(:env_config).with(no_args) do
    method.call.merge(
      'action_dispatch.show_exceptions' => true,
      'action_dispatch.show_detailed_exceptions' => false,
      'consider_all_requests_local' => false
    )
  end
end

This allows the test to work regardless of the order of execution of spec files. I don't know why but I also had to leave show_detailed_exceptions otherwise I wasn't getting the desired results.

Posted by Alexander Todorov on Wed 27 April 2016

There are comments.

When making assertions inside a within block the assertion scope is limited to the element selected by the within() function, although it looks like you are asserting on the entire page!

scenario 'Pressing Escape closes autocomplete popup' do
  within('#new-broadcast') do
    find('#broadcast_field').set('Hello ')
      start_typing_name('#broadcast_field', '@Bret')
      # will fail below
      expect(page).to have_selector('.ui-autocomplete')
      send_keys('#broadcast_field', :escape)
  end
  expect(page).to have_no_selector('.ui-autocomplete')
end

The above code failed the first expect() and it took me some time before I figured it out. Capybara's test suite itself gives you the answer

it "should assert content in the given scope" do
  @session.within(:css, "#for_foo") do
    expect(@session).not_to have_content('First Name')
  end
  expect(@session).to have_content('First Name')
end

So know your frameworks and happy testing.

Posted by Alexander Todorov on Sun 24 April 2016

There are comments.

I've been re-factoring some RSpec tests and encountered a method which has been stubbed-out 2 times in a row. This of course led to problems when I tried to delete some of the code, which I deemed unnecessary. Using Treehouse's burger example I've recreated my use-case. Comments are in the code below:

class Burger
  attr_reader :options

  def initialize(options={})
    @options = options
  end

  def apply_ketchup(number=0)
    @ketchup = @options[:ketchup]
    # the number is passed from the tests below to make it easier to
    # monitor execution of this method.
    printf "Ketchup applied %d times\n", number
  end

  def apply_mayo_and_ketchup(number=0)
    @options[:mayo] = true
    apply_ketchup(number)
  end

  def has_ketchup_on_it?
    @ketchup
  end
end

describe Burger do
  describe "#apply_mayo_and_ketchup" do
    context "with ketchup and single stubs" do
      let(:burger) { Burger.new(:ketchup => true) }

      it "1: sets the mayo flag to true, ketchup is nil" do
        # this line stubs-out the apply_ketchup method
        # and @ketchup will remain nil b/c the original
        # method is not executed at all
        expect(burger).to receive(:apply_ketchup)
        burger.apply_mayo_and_ketchup(1)

        expect(burger.options[:mayo]).to eq(true)
        expect(burger.has_ketchup_on_it?).to be(nil)
      end

      it "2: sets the mayo and ketchup flags to true" do
        # this line stubs-out the apply_ketchup method
        # but in the end calls the non-stubbed out version as well
        # so that has_ketchup_on_it? will return true !
        expect(burger).to receive(:apply_ketchup).and_call_original
        burger.apply_mayo_and_ketchup(2)

        expect(burger.options[:mayo]).to eq(true)
        expect(burger.has_ketchup_on_it?).to eq(true)
      end
    end

    context "with ketchup and double stubs" do
      let(:burger) { Burger.new(:ketchup => true) }
      before {
        # this line creates a stub for the apply_ketchup method
        allow(burger).to receive(:apply_ketchup)
      }

      it "3: sets the mayo flag to true, ketchup is nil" do
        # this line creates a second stub for the fake apply_ketchup method
        # @ketchup will remain nil b/c the original method which sets its value
        # isn't actually executed. we may as well comment out this line and
        # this will not affect the test at all
        expect(burger).to receive(:apply_ketchup)
        burger.apply_mayo_and_ketchup(3)

        expect(burger.options[:mayo]).to eq(true)
        expect(burger.has_ketchup_on_it?).to be(nil)
      end

      it "4: sets the mayo and ketchup flags to true" do
        # this line creates a second stub for the fake apply_ketchup method.
        # .and_call_original will traverse up the stubs and call the original
        # method. If we don't want to assert that the method has been called
        # or we don't care about its parameters, but only the end result
        # that system state has been changed then this line is redundant!
        # Don't stub & call the original, just call the original method, right?
        # Commenting out this line will cause a failure due to the first stub
        # in before() above. The first stub will execute and @ketchup will remain
        # nil! To set things straight also comment out the allow() line in
        # before()!
        expect(burger).to receive(:apply_ketchup).and_call_original
        burger.apply_mayo_and_ketchup(4)

        expect(burger.options[:mayo]).to eq(true)
        expect(burger.has_ketchup_on_it?).to eq(true)
      end
    end
  end
end

When I see a .and_call_original method after a stub I immediately delete it because in most of the cases this isn't necessary. Why stub out something just to call it again later ? See my comments above. Also the expect to receive && do action sequence is a bit counter intuitive. I prefer the do action & assert results sequence instead.

The problem here comes from the fact that RSpec has very flexible syntax for creating stubs which makes it very easy to abuse them, especially when you have no idea what you're doing. If you write tests with RSpec please make a note of this and try to avoid this mistake.

If you'd like to learn more about stubs see Bad Stub Design in DNF.

Posted by Alexander Todorov on Thu 31 March 2016

There are comments.

One of my tests was faiing and it turned out this was caused by a floating-point precision error. The functionality in question was a "Load more" button with pagination which loads records from the database and the front-end displays them.

Ruby and JavaScript were passing around a parameter which was only used as part of the SQL queries. Now the problem is that JavaScript doesn't have a Time class and the parameter was passed as string, then converted back to Time in Ruby. The problem comes from the intermediate conversion to float which was used.

Here's a little code snippet to demonstrate the problem:

irb(main):068:0* now = Time.now
=> 2016-03-08 10:54:26 +0200
irb(main):069:0> 
irb(main):070:0* Time.at(now) == now
=> true
irb(main):071:0> 
irb(main):072:0* Time.at(now.to_f) == now
=> false
irb(main):073:0> 
irb(main):074:0* now.to_f
=> 1457427266.7206197
irb(main):075:0> 
irb(main):076:0* now.strftime('%Y-%m-%d %H:%M:%S.%9N')
=> "2016-03-08 10:54:26.720619705"
irb(main):077:0> 
irb(main):079:0* Time.at(now.to_f).strftime('%Y-%m-%d %H:%M:%S.%9N')
=> "2016-03-08 10:54:26.720619678"
irb(main):080:0>

As you can see the conversion to float and back to Time is off by a few nano-seconds and the database either didn't return any records or was returning the same set of records. This isn't something you can usually see in production, right ? Unless you have huge traffic and happen to have records created exactly at the same moment.

The solution is to simply send Time.now.strftime to the JavaScript and then use Time.parse to reconstruct the value.

irb(main):077:0> 
irb(main):001:0> require 'time'
=> true
irb(main):002:0> Time.parse(now.strftime('%Y-%m-%d %H:%M:%S.%9N')).strftime('%Y-%m-%d %H:%M:%S.%9N')
=> "2016-03-08 10:54:26.720619705"
irb(main):003:0>

If you'd like to read more about floating point arithmetics please see http://floating-point-gui.de.

Posted by Alexander Todorov on Tue 08 March 2016

There are comments.

Publishing this mostly for self reference. Here are two blog posts on the topic of testing time dependent code in Ruby applications:

Synchronized Times In Ruby & JavaScript Acceptance Tests Using Capybara, Timecop & Sinon.JS

Move Over Timecop…Hello ActiveSupport::Testing::TimeHelpers

I haven't seen a module similar to timecop in Python, but frankly I've never needed one either.

Posted by Alexander Todorov on Tue 23 February 2016

There are comments.

During my quest for faster RSpec tests I've come across several interesting posts about Ruby. Being new to the language they've helped me understand a bit more about the internals. Posting them here so they don't get lost.

Garbage Collection

The road to faster tests - a story about tests and garbage collection.

Tuning Ruby garbage collection for RSpec - practical explanation of Ruby's garbage collector and how to adjust its performance for RSpec

Demystifying the Ruby GC

Probably the very first posts I found referencing slow RSpec tests. It turned out this was not the issue but I've nevertheless tried running GC manually. I can clearly see (using puts GC.count in after()) GC invoked less frequently, memory usage rising but the overall execution time wasn't affected. The profiler said 2% speed increase to be honest.

Profiling

Not being very clear about the different profiling tools available and how to interpret their results I've found these articles:

Profiling Ruby With Google's Perftools - practical example for using perftools.rb

How to read ruby profiler's output - also see the Profiler__ module

Show runtime for each rspec example - using rspec --profile

Suggestions for Faster Tests

Several general best practices for faster tests:

9 ways to speed up your RSpec tests

Run faster Ruby on Rails tests

Three tips to improve the performance of your test suite

RubyGems related

I've noticed Bundler loading tons of requirements (nearly 3000 unique modules) and for some particular specs this wasn't necessary (for example running Rubocop). I've found the following articles below which sound very reasonable to me:

Use Bundler.setup Instead of Bundler.require

5 Reasons to Avoid Bundler.require

Why "require 'rubygems'" Is Wrong

Weird

Finally (or more precisely first of all) I've seen this Weird performance issue.

During my initial profiling I've seen (and still see) a similar issue. When calling require it goes through lots of hoops before finally loading the module. My profiling results show this taking a lot of time but this time is likely measured with profiling enabled and doesn't represent the real deal.

On my MacBook Air with Red Hat Enterprise Linux 7 this happens when using Ruby 2.2.2 from Software Collections. If using Ruby installed from source with rbenv the profiling profile is completely different.

I will be examining this one in more details. I'm interested to know what is the difference and if that affects performance somehow so stay tuned!

Posted by Alexander Todorov on Wed 23 December 2015

There are comments.

I've been working with Tradeo on testing one of their applications. The app is standard Ruby on Rails application with over 1200 tests written with RSpec. And they were horribly slow. On my MacBook Air the entire test suite took 27 minutes to execute. On the Jenkins slaves it took over an hour. After a few changes Jenkins now takes 15 minutes to execute the test suite. Locally it takes around 11 minutes!

The Problem

I've measured the speed (with Time.now) at which individual examples execute and it was quickly apparent they were taking a lot of time cleaning the DB. The offending code in question was:

config.before(:all) do
  DatabaseCleaner.clean_with :truncation
end

This is truncating the tables quite often but it turns out this is a very expensive operation on tables with small number of records. I've measured it locally around 2.5 seconds. Check out this SO thread which describes pretty much the same symptoms:

Right now, locally (on a Macbook Air) a full test suite takes 28 minutes....
Tailing the logs on our CI server (Ubuntu 10.04 LTS) .... a build takes 84 minutes.

This excellent answer explains why this is happening:

(a) The bigger shared_buffers may be why TRUNCATE is slower on the CI server.
    Different fsync configuration or the use of rotational media instead of
    SSDs could also be at fault.

(b) TRUNCATE has a fixed cost, but not necessarily slower than DELETE,
    plus it does more work.

The Fix

config.before(:suite) do
  DatabaseCleaner.clean_with :truncation
end

config.before(:all) do
  DatabaseCleaner.clean_with :deletion
end

before(:suite) will truncate tables every time we run rspec, which is when we launch the entire test suite. This is to account for the possible side effects of DELETE in the future (see the SO thread). Then before(:all) aka before(:context) simply deletes the records which is significantly faster!

Also updated the CI servers postgresql.conf to

fsync=off
full_page_writes=off

The entire build/test process now takes only 15 minutes! Only one test broke due to PostgreSQL returning records in a different order, but it's the test case fault not handling this in the first place!

NOTE: Using fsync=off with rotational media pretty much hides any improvements introduced by updating the DatabaseCleaner strategy.

What's Next

There are several other things worth trying:

• Use UNIX domain sockets instead of TCP/IP (localhost) to connect to PostgreSQL;
• Load the entire PostgreSQL partition in memory;
• Don't delete anything from the database, except once in before(:suite). If any tests need a particular DB state they have to set this up on their own instead of relying on a global cleanup process. I expect this to break quite a few examples.

After the changes and with my crude measurements I have individual examples taking 0.31 seconds to execute. Interestingly before and after take less than a second while the example code takes around 0.15 seconds. I have no idea where the rest 0.15 seconds are spent. My current speculation is probably RSpec. This is 50% of the execution time and is also worth looking into!

Posted by Alexander Todorov on Wed 23 December 2015

There are comments.