basho/riak_test — pull request #105 by jrwest (2012-12-01 01:41:34+00:00)
Title: verify_busy_dist_port: remove use of grep via os:cmd, timer:sleep

ran into what I think is a subtle race condition while implementing the improved version of the `verify_busy_dist_port` test @joedevivo and I discussed so submitting a PR for my PR: https://github.com/basho/riak_test/pull/103.

the tl;dr of below goes something like: this is an improved implementation of the test but i think no matter what the test will need some from of periodic retry + max retry.

bit of background:
* the test registers a `riak_sysmon` handler to monitor for `busy_dist_port` events on the riak node
* it also registers a `riak_test_lager_backend`on the riak node to capture log messages in memory
* the riak node already has the `riak_core_sysmon_handler` installed before installing the test's handler. side note: `riak_core_sysmon_handler` is for the most part what we are testing (make sure `riak_sysmon` fires the `busy_dist_port` event, which is handled by `riak_core_sysmon_handler`, which subsequently logs the event).

attempt at describing the race condition:

1. the vm fires the busy_dist_port event, which propagates to bolth
`riak_core_sysmon_handler` and `verify_bdp_event_handler` via `gen_event:notify` .

2. `verify_bdp_event_handler:handle_event/2` and
`riak_core_sysmon_handler:handle_event/2` execute concurrently. the former
sends a message to the test process. the latter calls `lager:info`
(if functioning correctly) to log the BDP event.

3. when logging, as i understand it, lager calls `gen_event:sync_notify`
which waits for a reply from each backend (including `riak_test_lager_backend`).
4. when the test process receives the message from `verify_bdp_event_handler`
that it the BDP event fired the test process does a `gen_event:call` to `riak_test_lager_backend` for the logs.

3 & 4 is where the race starts. If somehow the message from `gen_event:call` (4) reaches the inbox of `riak_test_lager_backend` before the `gen_event:sync_notify` (3) the test fails although the message was correctly logged. In practice, I haven't seen this yet because its basically a inter-vm message in 4 trying to beat out an intra-vm message in 3 but its possible. However, I noticed this because I originally tried to have `verify_bdp_event_handler` call `riak_test_lager_backend:get_logs/0` instead of the test process. In that case, the test would fail improperly about 90% of the time.

So like the tl;dr says, basically i think we need a little periodic retry in the test still just to make it bulletproof but besides that i think this method is an improvement over the calls out to `grep` plus periodic sleeping in the first implementation.