mocked modules are not returned to normal state when verify/1 returns

[cypherfox]

Sometime after the switch to gen_statem (it may be completelely unconnected to that change) I regularly get errors like the one below.

When inserting a timer:sleep(100) after the em:verify/1 in the previous test of my eunit suite all works fine. I have started to add a sleep after every verify to work around this.

I have had a look at the code, but cannot find a race condition (at least no according to the documentation of the Erlang API functions that are called by erlymock)

=ERROR REPORT==== 29-Nov-2017::18:23:46 ===
** State machine <0.4811.0> terminating
** Last event = {{call,{<0.4809.0>,#Ref<0.4180725794.4003201027.186836>}},
                 {replay,infinity}}
** When server state  = {programming,
                         {state,<0.4809.0>,infinity,
                          [{expectation,#Ref<0.4180725794.4003201027.186833>,
                            {root,#Ref<0.4180725794.4003201027.186829>},
                            quperl_client_event_mgr,new_object,
                            [<<1,2,3,4>>],
                            {return,ok},
                            []},
                           {expectation,#Ref<0.4180725794.4003201027.186831>,
                            {root,#Ref<0.4180725794.4003201027.186829>},
                            quperl_client_cache,create_object,
                            [<<1,2,3,4>>,[{name,"foo"}]],
                            {return,ok},
                            []}],
                          [],
                          [{expectation,#Ref<0.4180725794.4003201027.186835>,
                            {root,#Ref<0.4180725794.4003201027.186829>},
                            quperl_client_event_mgr,fail,
                            [#Fun<quperl_client_util.is_object_id.1>,
                             txn_mgr_terminated],
                            {return,ok},
                            []}],
                          [],[],[],undefined,no_error}}
** Reason for termination = error:{bad_return_from_state_function,
                                   {em_error_module_already_mocked,
                                    quperl_client_event_mgr}}
** Callback mode = state_functions
** Stacktrace =
**  [{gen_statem,parse_event_result,8,[{file,"gen_statem.erl"},{line,1318}]},
     {gen_statem,loop_event,6,[{file,"gen_statem.erl"},{line,1015}]},
     {proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,247}]}]

[sheyll]

Thanks for reporting. I will try to reproduce this, then fix it. Do you have a failing minimal self contained test case?

[cypherfox]

Unfortunately not. This seems to be a classical heisenbug. I have test modules with >20 test cases run fine on my local, fairly fast machine, as well as on our CI pipeline server, then suddenly either may act up. Sometimes a retry of the whole test suite works, sometimes not. I have just started to add these sleeps without further reflection, as I need the tests to run.
It is time wasted, better the computers time than mine ;-)

[sheyll]

Thanks for reporting, we use em for production code, too, and I know about heisenbugs in unit tests

[sheyll]

I still haven't figured it out, I will meet a guy tomorrow, who might be able to help...

[cypherfox]

Thank you for staying on it.

[sheyll]

Ok, I can reproduce it now.
If it helps temporarily, things seem to work with 6.0.0-dev.

[sheyll]

I hope this finally fixes it... but since it is a Heisenbug, we'll have to see.

[cypherfox]

Yes, it seems to do the trick. Many thanks for the great work.

[sheyll]

Oh well... still breaks our tests :/

Another version is on its way.

[sheyll]

Version 7.2.2 is out, and it should fix this.

[cypherfox]

Hmm..no. I go lots of those after turning to 7.2.2. The test was running with 7.1.0:

=ERROR REPORT==== 20-Feb-2018::04:56:39 ===
** State machine <0.8172.0> terminating
** Last event = {{call,{<0.8158.0>,#Ref<0.3074200492.3073638401.158745>}},
                 {replay,infinity}}
** When server state  = {programming,
                            {state,<0.8158.0>,infinity,[],[],[],[],
                                [lb_server_locator],
                                undefined,no_error}}
** Reason for termination = error:{bad_return_from_state_function,
                                   {'failed to load modules',
                                    {error,
                                     'erly-mock moduler loading server internal error, please report this error'}}}
** Callback mode = state_functions
** Stacktrace =
**  [{gen_statem,parse_event_result,8,[{file,"gen_statem.erl"},{line,1318}]},
     {gen_statem,loop_event,6,[{file,"gen_statem.erl"},{line,1015}]},
     {proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,247}]}]

[cypherfox]

Things worked after a fashion with 7.1.0.

The only case where the mocked module was not released seem to be when;

M = em:new(),
em:strict(M, module_a, func1, []),
Step = em:strict(M, module_b, func2, []),
em:replay(M)

Pid = module_c:start_link(),

em:await(M, Step),
em:verify(M),

module_c:stop(Pid),

where the module_c:stop/1 would call a function in module_b. If I wait a few hundred miliseconds before module_c:stop/1, it worked fine with 7.1.0.

Yes, I could mock the last function to be called in module_b as well, but we have lot of bad tests, that will take some time to do. :(

[sheyll]

Ok ... I will try to make a test-case out of your example and then try to fix it, if it breaks...