Problem with mocking :timer?

[brentonannan]

I'm working in elixir, and have a GenServer that sleeps and casts to itself (it polls an Atom feed that is expected to be updated every few seconds):

  def handle_cast(:wait_and_poll, state) do
    :timer.sleep(state.poll_interval)
    GenServer.cast(self, :poll)
    {:noreply, state}
  end 

I'd like to mock :timer.sleep, so that (a) I can regression test the behaviour, and (b) I don't have to actually sleep during my tests; this is what I'm trying to do:

  test "handle_cast :wait_and_poll sleeps for poll_interval ms" do
    new(:timer, [:unstick])
    expect(:timer, :sleep, fn(777) -> :ok end)

    StreamPoller.handle_cast(:wait_and_poll, %{poll_interval: 777})

    validate(:timer)
    unload(:timer)
  end

The test bails out, with no real explanation:

$ iex -S mix test test/event_store/stream_poller_test.exs:42 --trace
Erlang/OTP 18 [erts-7.1] [source] [64-bit] [smp:8:8] [async-threads:10] [hipe] [kernel-poll:false]

Compiled lib/event_store/stream.ex
Compiled lib/event_store/config.ex
Compiled lib/event_store/stream_poller/supervisor.ex
Compiled lib/event_store/application.ex
Compiled lib/event_store/event.ex
Compiled lib/event_store/stream_poller.ex
Compiled lib/event_store.ex
Generated event_store app
Including tags: [line: "42"]
Excluding tags: [:test]


EventStore.StreamPollerTest
  * init casts :poll to self to start polling (skipped)
  * start calls Supervisor.start_child (skipped)
  * init sets default options if none given (skipped)
  * handle_cast :wait_and_poll does not alter state (skipped)
  * handle_cast :wait_and_poll casts :poll to self (skipped)
  * handle_cast :wait_and_poll sleeps for poll_interval ms** (EXIT from #PID<0.57.0>) killed

It seems to die during the line: expect(:timer, :sleep, fn(777) -> :ok end). Could this be a problem with mocking :timer, or am I just doing something wrong?

Other than this, I'm rather enjoying meck for mocking out my side-effects, so thanks!

[eproxus]

Hi, thanks for using Meck!

I cannot really answer why there is no output, this could be Elixir, ExUnit, your code, Meck or anything in-between. 😄

A couple of ideas:

• Someone else wants to use :timer.sleep/1 during the test and it fails with a function clause that is catched or hidden somewhere.

  You can avoid this by defining the expect like so: expect(:timer, :sleep, fn(777) -> :ok; (t) -> passthrough([t]) end).

• You're not reaching the unloading of the mock after the test and it causes problems down the line (although this should be visible somewhere, I guess).

You can try this in the top of your test case to see if you can spot where it is crashing:

test "..." do
  :dbg.tracer
  :dbg.p(:all, :call)
  :dbg.tp(mod, func, :x)

  # Your test case

  :dbg.stop_clear
end

Where mod and func are module names and functions names as atoms. This will print out all calls and return values. For example, :dbg.tp(:meck, :x) would show all function calls to the meck module. You might also need to turn of parallel runs of test cases in case it gets messy.

[brentonannan]

Hey, thanks for getting back to me so quick, and thanks a heap for the tips on using :dbg. I was thinking that it might be some quirk of mocking :timer (I've learned not to trust time based stuff in tests in general), so figured it was worth asking.

It looks like meck is behaving itself, and there's some other gen_server.call/2 in my test process that's breaking. Closing this issue as not related to meck... probably =P

Thanks again, and cheers for your work on a great project.

[eproxus]

Sure, just let me know if there is anything wrong with Meck in this case, or if something could be improved.

[brentonannan]

Gday again.

So it looks like it is something breaking within :meck, although my erlang debugging skills aren't up to scratch yet. I've found that :meck.new(:timer, [:unstick]) works fine, but both expect and unload are breaking (whichever comes first).

If you're interested in having a look, there's a minimal failing test here: https://github.com/brentonannan/meck_timer. Of course, I'll continue to try debugging it myself, but would welcome any help you can offer. I'll leave any notes in the readme. Cheers.

[eproxus]

After taking a look at your reproduction repo (thanks a lot, that really helped!) I have the suspicion that this is because timer is reloaded twice. Let me explain:

Cause

When Meck manipulates a module, the module with that name is recompiled (either replaced with a mock or with the original) and loaded.

In Erlang, only two versions of a module is kept in memory. If you continuously reload a module, it will always push out the oldest version and keep the last and current version. When a process call a module, it will always call the latest version of that module. If that module then calls local functions the process will stay in that version of the module (i.e. only fully qualified function calls, using the module and function name, will "migrate" to the latest version). Any process that lingers in the oldest version of the module, will get killed when a new version is loaded.

What I suspect is happening here, is that some code (probably related to ExUnit, which has some calls to :timer) uses the :timer.sleep function while timer is being reloaded twice (which then kill the timer process). That process is in turn linked to the test process which is in turn linked to the Meck process (which are all killed).

Solution

The only way to solve this is to not mock timer. 😄 Wrap it in your own module, and mock that one instead.

I tried using the :unlink option to Meck, but it didn't really help since the test process gets killed anyway.

[eproxus]

Added a caveat to the readme in 6eacbd7

[brentonannan]

Yeah, I had a feeling something like that was going on, but after digging around in meck_code, I decided I didn't know enough about erlang debugging to get to the point that you have there. Thanks so much for taking the time to look at it!

[eproxus]

No problem, it was an interesting case to debug. 😄