basho/riak_test — pull request #567 by kellymclaughlin (2014-04-09 19:44:20+00:00)
Title: Investigate occasional failure of verify_dynamic_ring test

Giddyup results show occasional failures for `verify_dynamic_ring` such as [this](http://giddyup.basho.com/#/projects/riak_ee/scorecards/94/94-714-verify_dynamic_ring-centos-6-64-memory) one. I have been able to reproduce the failure locally as well.

Investigate the failure to ensure the issue lies with the test and is not a bug in Riak.

The problem occurs when the test attempts to do a force-replace of a node while doing a ring resize. It starts at [L58](https://github.com/basho/riak_test/blob/master/tests/verify_dynamic_ring.erl#L58) of the test module.

The last console output from riak_test before the failure is this:

```
12:56:50.343 [info] verifying data written during operation
12:56:50.612 [info] verifying previously written data
12:56:51.131 [info] testing force-replace during resize
12:56:54.241 [info] Wait until ring converged on ['dev1@127.0.0.1','dev2@127.0.0.1','dev3@127.0.0.1','dev4@127.0.0.1']
12:56:54.767 [info] Wait until no pending changes on ['dev1@127.0.0.1','dev3@127.0.0.1','dev4@127.0.0.1']
13:08:59.976 [error] Error in process <0.187.0> on node 'riak_test@127.0.0.1' with exit value: {{assertEqual_failed,[{module,rt},{line,610},{expression,"wait_until ( F )"},{expected,ok},{value,{fail,false}}]},[{rt,'-wait_until_no_pending_changes/1-fun-3-',2,[{file,"src/rt.erl"},{line,610}]},{rt,wait_until_no_pending_changes...

13:08:59.976 [warning] verify_dynamic_ring failed: {{assertEqual_failed,[{module,rt},{line,610},{expression,"wait_until ( F )"},{expected,ok},{value,{fail,false}}]},[{rt,'-wait_until_no_pending_changes/1-fun-3-',2,[{file,"src/rt.erl"},{line,610}]},{rt,wait_until_no_pending_changes,1,[{file,"src/rt.erl"},{line,610}]},{verify_dynamic_ring,confirm,0,[{file,"tests/verify_dynamic_ring.erl"},{line,70}]}]}
13:08:59.977 [error]
================ verify_dynamic_ring failure stack trace =====================
{{assertEqual_failed,[{module,rt},
{line,610},
{expression,"wait_until ( F )"},
{expected,ok},
{value,{fail,false}}]},
[{rt,'-wait_until_no_pending_changes/1-fun-3-',2,
[{file,"src/rt.erl"},{line,610}]},
{rt,wait_until_no_pending_changes,1,[{file,"src/rt.erl"},{line,610}]},
{verify_dynamic_ring,confirm,0,
[{file,"tests/verify_dynamic_ring.erl"},{line,70}]}]}
==============================================================================

13:08:59.977 [notice] verify_dynamic_ring Test Run Complete

Test Results:
verify_dynamic_ring-memory: fail
---------------------------------------------
1 Tests Failed
0 Tests Passed
That's 0.0% for those keeping score
```
Here is console.log output from a case when the problem occurs:

```
2014-04-07 13:06:24.797 [error] <0.28365.0>@riak_core_handoff_sender:start_fold:279 resize_transfer transfer of riak_kv_vnode from 'dev3@127.0.0.1' 182687704666362864775460604089535377456991567872 to 'dev2@127.0.0.1' 1392993748081016843912887106182707253109560705024 failed because of exit:{{nodedown,'dev2@127.0.0.1'},{riak_core_gen_server,call,[{riak_kv_handoff_listener,'dev2@127.0.0.1'},handoff_port,infinity]}} [{riak_core_gen_server,call,3,[{file,"src/riak_core_gen_server.erl"},{line,230}]},{riak_core_handoff_sender,start_fold,5,[{file,"src/riak_core_handoff_sender.erl"},{line,102}]}]
2014-04-07 13:06:24.797 [error] <0.28368.0>@riak_core_handoff_sender:start_fold:279 resize_transfer transfer of riak_kv_vnode from 'dev3@127.0.0.1' 456719261665907161938651510223838443642478919680 to 'dev2@127.0.0.1' 296867520082839655260123481645494988367611297792 failed because of exit:{{nodedown,'dev2@127.0.0.1'},{riak_core_gen_server,call,[{riak_kv_handoff_listener,'dev2@127.0.0.1'},handoff_port,infinity]}} [{riak_core_gen_server,call,3,[{file,"src/riak_core_gen_server.erl"},{line,230}]},{riak_core_handoff_sender,start_fold,5,[{file,"src/riak_core_handoff_sender.erl"},{line,102}]}]
2014-04-07 13:06:25.300 [error] <0.28377.0>@riak_core_handoff_sender:start_fold:279 resize_transfer transfer of riak_kv_vnode from 'dev3@127.0.0.1' 182687704666362864775460604089535377456991567872 to 'dev2@127.0.0.1' 1392993748081016843912887106182707253109560705024 failed because of exit:{{nodedown,'dev2@127.0.0.1'},{riak_core_gen_server,call,[{riak_kv_handoff_listener,'dev2@127.0.0.1'},handoff_port,infinity]}} [{riak_core_gen_server,call,3,[{file,"src/riak_core_gen_server.erl"},{line,230}]},{riak_core_handoff_sender,start_fold,5,[{file,"src/riak_core_handoff_sender.erl"},{line,102}]}]
2014-04-07 13:06:25.300 [error] <0.28381.0>@riak_core_handoff_sender:start_fold:279 resize_transfer transfer of riak_kv_vnode from 'dev3@127.0.0.1' 456719261665907161938651510223838443642478919680 to 'dev2@127.0.0.1' 296867520082839655260123481645494988367611297792 failed because of exit:{{nodedown,'dev2@127.0.0.1'},{riak_core_gen_server,call,[{riak_kv_handoff_listener,'dev2@127.0.0.1'},handoff_port,infinity]}} [{riak_core_gen_server,call,3,[{file,"src/riak_core_gen_server.erl"},{line,230}]},{riak_core_handoff_sender,start_fold,5,[{file,"src/riak_core_handoff_sender.erl"},{line,102}]}]
2014-04-07 13:06:25.300 [error] <0.28379.0>@riak_core_handoff_sender:start_fold:279 resize_transfer transfer of riak_kv_vnode from 'dev3@127.0.0.1' 730750818665451459101842416358141509827966271488 to 'dev2@127.0.0.1' 365375409332725729550921208179070754913983135744 failed because of exit:{{nodedown,'dev2@127.0.0.1'},{riak_core_gen_server,call,[{riak_kv_handoff_listener,'dev2@127.0.0.1'},handoff_port,infinity]}} [{riak_core_gen_server,call,3,[{file,"src/riak_core_gen_server.erl"},{line,230}]},{riak_core_handoff_sender,start_fold,5,[{file,"src/riak_core_handoff_sender.erl"},{line,102}]}]
2014-04-07 13:06:25.302 [error] <0.28383.0>@riak_core_handoff_sender:start_fold:279 resize_transfer transfer of riak_kv_vnode from 'dev3@127.0.0.1' 1278813932664540053428224228626747642198940975104 to 'dev2@127.0.0.1' 1118962191081472546749696200048404186924073353216 failed because of exit:{{nodedown,'dev2@127.0.0.1'},{riak_core_gen_server,call,[{riak_kv_handoff_listener,'dev2@127.0.0.1'},handoff_port,infinity]}} [{riak_core_gen_server,call,3,[{file,"src/riak_core_gen_server.erl"},{line,230}]},{riak_core_handoff_sender,start_fold,5,[{file,"src/riak_core_handoff_sender.erl"},{line,102}]}]
```
`dev2@127.0.0.1` is the node that has been force-replaced.

`riak-admin member-status` output:

```
================================= Membership ==================================
Status Ring Pending Node
-------------------------------------------------------------------------------
valid 37.5% 34.4% 'dev1@127.0.0.1'
valid 31.3% 32.8% 'dev3@127.0.0.1'
valid 31.3% 32.8% 'dev4@127.0.0.1'
-------------------------------------------------------------------------------
Valid:3 / Leaving:0 / Exiting:0 / Joining:0 / Down:0
```

`riak-admin ring-status` output:

```
================================== Claimant ===================================
Claimant: 'dev1@127.0.0.1'
Status: up
Ring Ready: true

============================== Ownership Handoff ==============================
Owner: dev1@127.0.0.1
Next Owner: $resize

Index: 0
All transfers complete. Waiting for claimant to change ownership.

Index: 274031556999544297163190906134303066185487351808
All transfers complete. Waiting for claimant to change ownership.

Index: 548063113999088594326381812268606132370974703616
All transfers complete. Waiting for claimant to change ownership.

Index: 822094670998632891489572718402909198556462055424
All transfers complete. Waiting for claimant to change ownership.

Index: 1096126227998177188652763624537212264741949407232
All transfers complete. Waiting for claimant to change ownership.

Index: 1370157784997721485815954530671515330927436759040
All transfers complete. Waiting for claimant to change ownership.

-------------------------------------------------------------------------------
Owner: dev3@127.0.0.1
Next Owner: $resize

Index: 182687704666362864775460604089535377456991567872
Waiting on: [riak_kv_vnode]
Complete: [riak_pipe_vnode]

Index: 456719261665907161938651510223838443642478919680
Waiting on: [riak_kv_vnode]
Complete: [riak_pipe_vnode]

Index: 730750818665451459101842416358141509827966271488
Waiting on: [riak_kv_vnode]
Complete: [riak_pipe_vnode]

Index: 1004782375664995756265033322492444576013453623296
All transfers complete. Waiting for claimant to change ownership.

Index: 1278813932664540053428224228626747642198940975104
Waiting on: [riak_kv_vnode]
Complete: [riak_pipe_vnode]

-------------------------------------------------------------------------------
Owner: dev4@127.0.0.1
Next Owner: $resize

Index: 91343852333181432387730302044767688728495783936
All transfers complete. Waiting for claimant to change ownership.

Index: 365375409332725729550921208179070754913983135744
All transfers complete. Waiting for claimant to change ownership.

Index: 639406966332270026714112114313373821099470487552
All transfers complete. Waiting for claimant to change ownership.

Index: 913438523331814323877303020447676887284957839360
All transfers complete. Waiting for claimant to change ownership.

Index: 1187470080331358621040493926581979953470445191168
All transfers complete. Waiting for claimant to change ownership.

-------------------------------------------------------------------------------
```

`riak-admin transfers` output:

```
'dev4@127.0.0.1' waiting to handoff 25 partitions
'dev3@127.0.0.1' waiting to handoff 15 partitions
'dev1@127.0.0.1' waiting to handoff 16 partitions

Active Transfers:
```