Getting "unexpected termination of test process"

[kjw1]

I have an eunit test where I'm trying to meck some other modules I'm also testing. Is this supposed to work? For some reason this works on my dev machine, but not on my build machine.

Running Erlang 16B03 on both, rebar 2.2 Dev machine is Mac OS X Mavericks Build machine is Ubuntu 12.04 LTS

======================== EUnit ========================
module 'twilio_api'
module 'chat_adapter_sup'
module 'chat_adapter_cluster_manager'
module 'chat_adapter_callbacks'
module 'xmpp_http_handler'
module 'chat_adapter_locator'
src/chat_adapter_locator.erl:36:<0.179.0>: mnesia : create_table ( Table , Options ) = {atomic,ok}
src/chat_adapter_locator.erl:36:<0.179.0>: mnesia : create_table ( Table , Options ) = {atomic,ok}
  chat_adapter_locator: locator_test_...ok
src/chat_adapter_locator.erl:59:<0.228.0>: Result = {adapter_mapping,<<"+1231231234">>,<<"anon@someserver">>,fake_pid}
  chat_adapter_locator: locator_test_...ok
src/chat_adapter_locator.erl:42:<0.179.0>: mnesia : delete_table ( Table ) = {atomic,ok}
src/chat_adapter_locator.erl:42:<0.179.0>: mnesia : delete_table ( Table ) = {atomic,ok}
  [done in 0.006 s]
module 'chat_adapter_history'
src/chat_adapter_history.erl:42:<0.179.0>: mnesia : create_table ( Table , Options ) = {atomic,ok}
src/chat_adapter_history.erl:57:<0.271.0>: Result = {chat_history,{{1399,409162,764718},<<"someemail@someserver">>},
                       <<"testuser@testserver">>,<<"someemail@someserver">>,
                       in,<<"some content!">>,
                       {1399,409162,764718}}
  chat_adapter_history: chat_history_test_...[0.001 s] ok
src/chat_adapter_history.erl:48:<0.179.0>: mnesia : delete_table ( Table ) = {atomic,ok}
  chat_adapter_history: date_to_list_test...[0.006 s] ok
  [done in 0.031 s]
module 'chat_adapter_app'
twilio_handler: handle_message_test (module 'twilio_handler')...*skipped*
undefined
*unexpected termination of test process*
::killed

=======================================================
  Failed: 0.  Skipped: 0.  Passed: 4.
One or more tests were cancelled.

=ERROR REPORT==== 6-May-2014::13:46:03 ===
** Generic server jabberer_meck terminating 
** Last message in was {'EXIT',<0.179.0>,killed}
** When Server state == {state,jabberer,
                               [{start_client,3},
                                {start_client,4},
                                {stop_client,2},
                                {send_message,3},
                                {stop_anonymous_client,2},
                                {start_anonymous_client,3},
                                {get_from_stanza,3}],
                               {dict,0,16,16,8,80,48,
                                     {[],[],[],[],[],[],[],[],[],[],[],[],[],
                                      [],[],[]},
                                     {{[],[],[],[],[],[],[],[],[],[],[],[],[],
                                       [],[],[]}}},
                               true,[],
                               {false,no_passthrough_cover},
                               false,undefined,[]}
** Reason for termination == 
** killed
=ERROR REPORT==== 6-May-2014::13:46:03 ===
** Generic server chat_adapter_locator_meck terminating 
** Last message in was {'EXIT',<0.179.0>,killed}
** When Server state == {state,chat_adapter_locator,
                         [{table_defs,0},
                          {locator_test_,0},
                          {find_adapter,1},
                          {find_convo,1},
                          {mapping_list,0},
                          {test,0},
                          {map_adapter,3},
                          {map_convo,2}],
                         {dict,1,16,16,8,80,48,
                          {[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},
                          {{[],[],[],[],[],[],[],[],[],[],[],[],[],
                            [[{find_adapter,1}|
                              {{find_adapter,1},
                               [{{args_matcher,['_'],<<>>,false},
                                 {meck_exec,
                                  #Fun<twilio_handler.1.30566776>}}]}]],
                            [],[]}}},
                         true,[],
                         {{"/home/denimbuild/hudson/workspace/ChatAdapter-Master/.eunit/chat_adapter_locator.beam",
                           "chat_adapter_locator.coverdata",
                           [{outdir,".eunit"},
                            debug_info,
                            {d,'TEST'},
                            debug_info,
                            {i,"include"}]},
                          <<70,79,82,49,0,0,27,140,66,69,65,77,65,116,111,109,
                            0,0,3,96,0,0,0,67,34,99,104,97,116,95,97,100,97,
                                  . . . lots of numbers . . .
                            111,99,97,116,111,114,46,101,114,108>>},
                         false,
                         {<0.307.0>,{<0.179.0>,#Ref<0.0.0.3275>}},
                         []}
** Reason for termination == 
** {{badmatch,{error,{cant_open_file,"chat_adapter_locator.coverdata",
                                     enoent}}},
    [{meck_proc,restore_original,3,[{file,"src/meck_proc.erl"},{line,526}]},
     {meck_proc,terminate,2,[{file,"src/meck_proc.erl"},{line,312}]},
     {gen_server,terminate,6,[{file,"gen_server.erl"},{line,719}]},
     {proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,239}]}]}

=ERROR REPORT==== 6-May-2014::13:46:03 ===
** Generic server chat_adapter_history_meck terminating 
** Last message in was {'EXIT',<0.179.0>,killed}
** When Server state == {state,chat_adapter_history,
                               [{table_defs,0},
                                {chat_history_test_,0},
                                {date_to_list_test,0},
                                {init,3},
                                {handle,2},
                                {terminate,3},
                                {test,0},
                                {record_message,4}],
                               {dict,0,16,16,8,80,48,
                                     {[],[],[],[],[],[],[],[],[],[],[],[],[],
                                      [],[],[]},
                                     {{[],[],[],[],[],[],[],[],[],[],[],[],[],
                                       [],[],[]}}},
                               true,[],
                               {{"/home/denimbuild/hudson/workspace/ChatAdapter-Master/.eunit/chat_adapter_history.beam",
                                 "chat_adapter_history.coverdata",
                                 [{outdir,".eunit"},
                                  debug_info,
                                  {d,'TEST'},
                                  debug_info,
                                  {i,"include"}]},
                                <<70,79,82,49,0,0,43,92,66,69,65,77,65,116,
                                  111,109,0,0,4,131,0,0,0,94,34,99,104,97,116,
                                  . . . lots of numbers . . .
                                  116,111,114,121,46,101,114,108,0>>},
                               false,undefined,[]}
** Reason for termination == 
** {{badmatch,{error,{cant_open_file,"chat_adapter_history.coverdata",
                                     enoent}}},
    [{meck_proc,restore_original,3,[{file,"src/meck_proc.erl"},{line,526}]},
     {meck_proc,terminate,2,[{file,"src/meck_proc.erl"},{line,312}]},
     {gen_server,terminate,6,[{file,"gen_server.erl"},{line,719}]},
     {proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,239}]}]}
Cover analysis: /home/denimbuild/hudson/workspace/ChatAdapter-Master/.eunit/index.html
Coverdata export: /home/denimbuild/hudson/workspace/ChatAdapter-Master/.eunit/eunit.coverdata

=INFO REPORT==== 6-May-2014::13:46:03 ===
    application: mnesia
    exited: killed
    type: temporary
ERROR: One or more eunit tests failed.
ERROR: eunit failed while processing /home/denimbuild/hudson/workspace/ChatAdapter-Master: rebar_abort
WARN:  Ignoring sub_dirs for /home/denimbuild/hudson/workspace/ChatAdapter-Master/deps/jabberer

[kjw1]

Here's the test I was trying to run:

handle_message_test() ->
  meck:new(chat_adapter_locator),
  meck:new(chat_adapter_history),
  meck:new(jabberer),
  meck:expect(chat_adapter_locator, find_adapter,
    fun(<<"from_phone_number">>) ->
      {<<"from_phone_number">>, <<"anon@someserver">>, fake_pid}
    end),
  meck:expect(chat_adapter_locator, find_convo,
    fun(<<"from_phone_number">>) ->
      {<<"from_phone_number">>, <<"somejid@someserver">>}
    end),
  meck:expect(chat_adapter_history, record_message,
    fun(<<"somejid@someserver">>, <<"from_phone_number">>, in, "some text!") ->
      ok
    end),
  meck:expect(jabberer, send_message,
    fun(fake_pid, <<"somejid@someserver">>, "some text!") ->
      ok
    end),
  handle_message([{<<"From">>, <<"from_phone_number">>}, {<<"Body">>, <<"some text!">>}]),
  meck:unload(jabberer),
  meck:unload(chat_adapter_history),
  meck:unload(chat_adapter_locator).

[eproxus]

Hmm, seems somehow to be related to the cover data that Meck exports. When mocking a module, Meck saves the cover data, creates the mock, and when unloaded, restores the original module and cover data. This temporary file seems to go missing in between these steps.

One possible solution would be to try to restore the data, but only if the file exists. It would be interesting to find out why it goes missing in the first place though.

[kjw1]

I'll try running the tests for meck on the machine and see if it fails anything, maybe I can figure out what the problem is.

[kjw1]

I think there has to be some sort of race condition, but I'm not sure what it is. The temporary files are created, since I can see them being written with inotify, so maybe that's why meck can't find them. Also, sometimes the files end up written to the project root directory, not the eunit directory. Not sure what causes that, either.

Just to see what would happen, I disabled the tests on a module I was trying to meck, and the tests ran fine.

Still poking around, will post more updates later.

[eproxus]

Do you run tests in parallel somehow? Could it be that you mock the same module twice somehow, like new(M), new(M), unload(M), unload(M) % Crash here?

[kjw1]

I'm only using meck in that one module. Even if eunit is running the tests in parallel, it shouldn't be mocking anything twice. I don't think I'm mocking the same module twice in this test, either. The test code is in one of my previous comments. I'll try to make a project that can replicate this behavior.

[kjw1]

I made a trivial project which fails, even on my dev machine:

https://github.com/kjw1/meck_test

EDIT: Whoops, might be an error in the test itself, let me fix that first

[kjw1]

Alright, I did some more experiments but I'm just more confused. First of all, I'm mocking 2 modules, chat_adapter_locator and chat_adapter history. If I have plain tests of the form:

some_test() ->
  ok = ok.

then it works. However, if I have a test generator:

some_test() ->
  {setup,
    fun() -> ok end,
    fun(_) -> ok end,
    fun(_) -> [ fun() -> ok = ok end ]
  }.

in one of those 2 modules, then it crashes. Right now I'm looking at covertool to see if that's causing issues. If that's the case I can try running that separately.

[kjw1]

Doesn't seem to be covertool, either. I managed to strip down my work project so it literally has no code in the modules I'm testing but it's still failing. I'll put it in my test app repo soon, maybe you can take a look and see if it works for you.

[kjw1]

It actually doesn't seem to have anything to do with cover at all. That is probably just a side effect of it crashing somewhere else. I don't have cover enabled anymore and it still crashes. I'm going to try this on another similar machine to make sure it still happens there.

[kjw1]

I checked on another Ubuntu 12.04 LTS machine, and the same bug still happens. The meck test repository I posted earlier has the broken code. Just run

rebar compile
rebar eunit skip_deps=true

and it should crash. Please let me know if you have time to take a look.

[Licenser]

I was seeing the same error, for me it turned out that I tried to unload a module I never mocked. Hope that helps you!

[kjw1]

I managed to solve my problem by not having the tests in the same file as the module. I'm guessing this model isn't compatible with the way meck works. Thanks for your suggestion.

[eproxus]

Were you mocking the same module you ran the test code from?

[kjw1]

No, it was a different module.

[dcsommer]

I can repro *unexpected termination of test process* ::killed by running two beam instances in parallel running the same tests in a loop. I straced the beam processes, and they did not ever operate on any coverdata files.

[eproxus]

@dcsommer The *unexpected termination of test process* ::killed messages comes from EUnit and doesn't necessarily have anything to do with Meck.

[dcsommer]

I should have left more details. The eunit process is crashing (causing that message) when I meck:unload() a module in the teardown of a {setup, _, _, _} test. I'll try to create a minimal repro program and report back.

[pselden]

https://github.com/eproxus/meck/issues/123#issuecomment-402217769 @dcsommer did you ever figure this out? I'm hitting the exact same issue (and am using the same test generator style and unloading there.

The strange part is this is the first time it happens in my project of about 50 files even though I'm using this pattern elsewhere.

It also matters what order the tests are run in -- I believe because it fails when I'm mecking a module it already tested.

Example:

rebar3 eunit -mmod_1,mod_2

mod2 has meck:new([mod_1) in the setup and meck:unload() in the teardown.

This crashes, but if I do rebar3 eunit -mmod_2,mod_1 it all works fine.

[dcsommer]

(Un?)fortunately my error disappeared and I was unable to repro it. If you have a 100% repro here, that is quite interesting. It is a known no-no to mock a module you are currently executing, but it seems like meck should be able to mock a previously loaded module.

On Fri, Aug 17, 2018 at 1:02 PM Paul Selden notifications@github.com wrote:

123 (comment)

https://github.com/eproxus/meck/issues/123#issuecomment-402217769 @dcsommer https://github.com/dcsommer did you ever figure this out? I'm hitting the exact same issue (and am using the same test generator style and unloading there.

The strange part is this is the first time it happens in my project of about 50 files even though I'm using this pattern elsewhere.

It also matters what order the tests are run in -- I believe because it fails when I'm mecking a module it already tested.

Example:

rebar3 eunit -mmod_1,mod_2

mod2 has meck:new([mod_1) in the setup and meck:unload() in the teardown.

This crashes, but if I do rebar3 eunit -mmod_2,mod_1 it all works fine.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/eproxus/meck/issues/123#issuecomment-413973873, or mute the thread https://github.com/notifications/unsubscribe-auth/ABCFINRTwX70XYTx8JNp3-mzTbjaa_Wbks5uRyE-gaJpZM4B4eLw .

[eproxus]

@pselden @dcsommer Are you both using unlink as an option or not? I assume it won't make a difference, since I have a hunch the problems are not Meck's fault. When Meck is reloading twice it kills some EUnit process that is lying around having references to the mocked module.

One test to reproduce/verify this could be to replace the mocking with a normal module reload to see if you can trigger the same problem.

[pselden]

I created a reproducible case here, but found out that it is only a problem in OTP 18 (my other project is also using that version still): https://github.com/pselden/test_meck_error

You can use ERLANG_VERSION=18 make to start a docker shell using the given erlang version (or use whatever you want for version switching locally) and then run rebar3 eunit. Crashes in 18, passes in 19.