Thursday, December 18, 2014

Testing Oddities with Amnesia

Background

I'm starting to write the tests for what I'm hoping will become a very simple set of tests to validate my Amnesia-based database.  The first test looks like this:
  PasteDB.Paste.wait
  test "Starting with an empty database" do
    assert(Amnesia.transaction! do PasteDB.Paste.keys end == [])
  end
Which makes sure my test database is empty before I start.

The second test is a little longer and more complex and looks like this:
  test "Direct insertion into Amnesia, sample data" do
    id = UUID.uuid1
    date = Timex.Date.now(:secs)
    expires = Timex.Date.now(:secs) + 2000
    title = "This is sample paste number one"
    public = true
    ircchannels = [:foo, :bar]
    previous_version =  nil
    content = "This is the first public paste content"

    assert(Amnesia.transaction! do %PasteDB.Paste{id: id, title: title, public: public, ircchannels: ircchannels, date: date, expires: expires, previous_version: previous_version, content: content} |> PasteDB.Paste.write end)

    Amnesia.transaction! do
      assert [id] == PasteDB.Paste.keys
    end
It inserts a single record into the (assured?) empty database above which means that when we pull back the list of keys, our list of keys should be an array with a single key which matches [id]

However when you run the test, you get this:
red@nukefromorbit:pastenix$ mix test
Running Pastenix.Endpoint with Cowboy on port 4001 (http)
...

Finished in 0.07 seconds (0.06s on load, 0.01s on tests)
3 tests, 0 failures
or this:
Running Pastenix.Endpoint with Cowboy on port 4001 (http)
..

  1) test Starting with an empty database (PasteDBTest)
     test/pastedb_test.exs:6
     Assertion with == failed
     code: Amnesia.transaction!() do
             PasteDB.Paste.keys()
           end == []
     lhs:  ["1efcefac-86c2-11e4-a9c8-600308a99134"]
     rhs:  []
     stacktrace:
       test/pastedb_test.exs:7
Randomly.

So what's going on here?

If I enable tracing in ExUnit by modifying the ExUnit.start function in test_helper.exs:

ExUnit.start(trace: true)
I get the gift of clarity.  Here's my two cases, spot the difference:
red@nukefromorbit:pastenix$ mix test
Running Pastenix.Endpoint with Cowboy on port 4001 (http)

PasteDBTest
  * Starting with an empty database (0.07ms)
  * Direct insertion into Amnesia, sample data (16.9ms)

PastenixTest
  * the truth (0.00ms)


Finished in 0.07 seconds (0.06s on load, 0.01s on tests)
3 tests, 0 failures
and

red@nukefromorbit:pastenix$ mix test
Running Pastenix.Endpoint with Cowboy on port 4001 (http)

PastenixTest
  * the truth (0.00ms)

PasteDBTest
  * Direct insertion into Amnesia, sample data (18.3ms)
  * Starting with an empty database (0.1ms)

  1) test Starting with an empty database (PasteDBTest)
     test/pastedb_test.exs:6
     Assertion with == failed
     code: Amnesia.transaction!() do
             PasteDB.Paste.keys()
           end == []
     lhs:  ["9327d4f0-86c2-11e4-aba2-600308a99134"]
     rhs:  []
     stacktrace:
       test/pastedb_test.exs:7


Finished in 0.07 seconds (0.05s on load, 0.02s on tests)
3 tests, 1 failures
Two differences immediately jump out at me.  The first is the ordering in which the two test suites PastenixTest and PasteDBTest execute.  The second is that the insertion test happens before the test for an empty set, the latter is obviously the cause of the test fail but is the former what causes the issue?

Removing all the other tests makes no difference, the tests still randomly fail.

So my tests all run in parallel?

Yup - pretty cool huh?  Mostly, well yes - can this be overridden?

The docs show an option you can pass to ExUnit.start which allows you to set the number of concurrent jobs to run so I can just set that to 1 and my tests will all run, one at a time in a nice predictable way right?

The assumptions of an imperative programmer...

Nope.

So I went digging into the ExUnit source-code to find out why and this is what I found in runner.ex:
{run_us, _} =
:timer.tc fn ->
  EM.suite_started(config.manager, opts)
  loop %{config | sync_cases: shuffle(config, sync),
     async_cases: shuffle(config, async)}
end

EM.suite_finished(config.manager, run_us, load_us)
EM.call(config.manager, ExUnit.RunnerStats, :stop, @stop_timeout)
Wait, what?

The test cases are shuffled(!) before execution!!?!

Let's look at the shuffle function:
defp shuffle(%{seed: 0}, list) do
    Enum.reverse(list)
end

defp shuffle(%{seed: seed}, list) do
  _ = :random.seed(3172, 9814, seed)
  Enum.shuffle(list)
end
So, if I pass seed: 0 in my ExUnix.start function then I avoid the shuffle. Success?!!??!?

So what did I learn?

If I use seed: 0 then what have I really achieved?  I've achieved subversion of a test that I didn't think of but the developer of ExUnit did.  In a concurrent world you have no guarantees as to the order in which things happen.

My mistake was in the first first paragraph of this post.  "The first test...".  First implies serialization which is the opposite of concurrency.  Serialization is the opposite of what I want.

Like a good imperative programmer my tests had side-effects by the very nature of my approach to the problem.  My insertion test had the side-effect of inserting a record changing state outside of itself.

This broke everything.

I'm clearly still not thinking in a functional way.  If something as simple as a shuffle of my tests (which is what concurrency does in the real world) can break my application's test suite then I'm doing it wrong.  My instinctive response was to try and serialize it to make it fit in my serial world.

So Thank You ExUnit developer for having my back when I didn't realize I left it exposed.

Mindset change required.  The battle continues...

No comments:

Post a Comment