insufficient_vnodes possible soon after node join

[rzezeski]

Today I have been able to reproduce the error below on every run of the yokozuna test. Currently, during yokozuna application startup, a KV get is performed. This get is performed after it waits for the riak_kv service but the preflist still comes up empty, i.e. [].

The issue is that at the moment the get is performed dev4 (which has just joined a 3-node cluster) owns none of the ring but is the only node in the riak_core_node_watcher. Thus UpNodes will consist of only dev4 and nothing from the ring will match--ultimately resulting in an empty preflist. The second paste below shows a print from riak_core_apl showing the ring with no dev4 owner and a node watcher with only dev4.

So the node watcher lags behind the ring update causing the node to temporarily have [] preflist for everything. I'm not sure this is easily solvable. We could add another stage to a node transition that lets it get ready before taking on requests but I'm not really sure what that all entails. I just wanted to dump my findings here before I lost the motivation to do so.

Error

** Reason for termination ==                                                                                                                                                                                                                
** {{case_clause,{<<"_yz_default">>,{error,{insufficient_vnodes,0,need,2}}}},[{yz_schema,get,1,    [{file,"src/yz_schema.erl"},{line,39}]},{yz_index,local_create,2,[{file,"src/yz_index.erl"},{line,75}]},{yz_events,add_index,2,[{file,"src/y\
z_events.erl"},{line,97}]},{yz_events,'-add_indexes/2-lc$^0/1-0-',2,[{file,"src/yz_events.erl"},{line,102}]},{yz_events,add_indexes,2,[{file,"src/yz_events.erl"},{line,102}]},{yz_events,sync_indexes,4,[{file,"src/yz_events.erl"},{line,\
234}]},{yz_events,handle_cast,2,[{file,"src/yz_events.erl"},{line,76}]},{gen_server,handle_msg,5,[{file,"gen_server.erl"},{line,607}]}]} 

riak_core_apl print out

2012-09-11 17:59:29.774 [warning] <0.1792.0>@riak_kv_get_fsm:prepare:162 KV {<<"_yz_schema">>,<<"_yz_default">>} UpNodes ['dev4@127.0.0.1'] node_watcher tab: [{{by_service,yokozuna},['dev4@127.0.0.1']},{{by_service,riak_pipe},['dev4@127.0.0.1']},{{by_node,'dev4@127.0.0.1'},[yokozuna,riak_kv,riak_pipe]},{{by_service,riak_kv},['dev4@127.0.0.1']},{'dev4@127.0.0.1',63514619969}]
2012-09-11 17:59:29.775 [warning] <0.1792.0>@riak_core_apl:get_apl_ann:79 APL ANN: ['dev4@127.0.0.1'] [{1050454301831586472458898473514828420377701515264,'dev2@127.0.0.1'},{1073290264914881830555831049026020342559825461248,'dev1@127.0.0.1'},{1096126227998177188652763624537212264741949407232,'dev1@127.0.0.1'}] [{1118962191081472546749696200048404186924073353216,'dev2@127.0.0.1'},{1141798154164767904846628775559596109106197299200,'dev2@127.0.0.1'},{1164634117248063262943561351070788031288321245184,'dev1@127.0.0.1'},{1187470080331358621040493926581979953470445191168,'dev1@127.0.0.1'},{1210306043414653979137426502093171875652569137152,'dev2@127.0.0.1'},{1233142006497949337234359077604363797834693083136,'dev2@127.0.0.1'},{1255977969581244695331291653115555720016817029120,'dev1@127.0.0.1'},{1278813932664540053428224228626747642198940975104,'dev1@127.0.0.1'},{1301649895747835411525156804137939564381064921088,'dev2@127.0.0.1'},{1324485858831130769622089379649131486563188867072,'dev2@127.0.0.1'},{1347321821914426127719021955160323408745312813056,'dev1@127.0.0.1'},{1370157784997721485815954530671515330927436759040,'dev1@127.0.0.1'},{1392993748081016843912887106182707253109560705024,'dev2@127.0.0.1'},{1415829711164312202009819681693899175291684651008,'dev2@127.0.0.1'},{1438665674247607560106752257205091097473808596992,'dev1@127.0.0.1'},{0,'dev1@127.0.0.1'},{22835963083295358096932575511191922182123945984,'dev2@127.0.0.1'},{45671926166590716193865151022383844364247891968,'dev3@127.0.0.1'},{68507889249886074290797726533575766546371837952,'dev3@127.0.0.1'},{91343852333181432387730302044767688728495783936,'dev1@127.0.0.1'},{114179815416476790484662877555959610910619729920,'dev2@127.0.0.1'},{137015778499772148581595453067151533092743675904,'dev3@127.0.0.1'},{159851741583067506678528028578343455274867621888,'dev3@127.0.0.1'},{182687704666362864775460604089535377456991567872,'dev1@127.0.0.1'},{205523667749658222872393179600727299639115513856,'dev2@127.0.0.1'},{228359630832953580969325755111919221821239459840,'dev3@127.0.0.1'},{251195593916248939066258330623111144003363405824,'dev3@127.0.0.1'},{274031556999544297163190906134303066185487351808,'dev1@127.0.0.1'},{296867520082839655260123481645494988367611297792,'dev2@127.0.0.1'},{319703483166135013357056057156686910549735243776,'dev3@127.0.0.1'},{342539446249430371453988632667878832731859189760,'dev3@127.0.0.1'},{365375409332725729550921208179070754913983135744,'dev1@127.0.0.1'},{388211372416021087647853783690262677096107081728,'dev2@127.0.0.1'},{411047335499316445744786359201454599278231027712,'dev3@127.0.0.1'},{433883298582611803841718934712646521460354973696,'dev3@127.0.0.1'},{456719261665907161938651510223838443642478919680,'dev1@127.0.0.1'},{479555224749202520035584085735030365824602865664,'dev2@127.0.0.1'},{502391187832497878132516661246222288006726811648,'dev3@127.0.0.1'},{525227150915793236229449236757414210188850757632,'dev3@127.0.0.1'},{548063113999088594326381812268606132370974703616,'dev1@127.0.0.1'},{570899077082383952423314387779798054553098649600,'dev2@127.0.0.1'},{593735040165679310520246963290989976735222595584,'dev3@127.0.0.1'},{616571003248974668617179538802181898917346541568,'dev3@127.0.0.1'},{639406966332270026714112114313373821099470487552,'dev1@127.0.0.1'},{662242929415565384811044689824565743281594433536,'dev2@127.0.0.1'},{685078892498860742907977265335757665463718379520,'dev3@127.0.0.1'},{707914855582156101004909840846949587645842325504,'dev3@127.0.0.1'},{730750818665451459101842416358141509827966271488,'dev1@127.0.0.1'},{753586781748746817198774991869333432010090217472,'dev2@127.0.0.1'},{776422744832042175295707567380525354192214163456,'dev3@127.0.0.1'},{799258707915337533392640142891717276374338109440,'dev3@127.0.0.1'},{822094670998632891489572718402909198556462055424,'dev1@127.0.0.1'},{844930634081928249586505293914101120738586001408,'dev2@127.0.0.1'},{867766597165223607683437869425293042920709947392,'dev3@127.0.0.1'},{890602560248518965780370444936484965102833893376,'dev3@127.0.0.1'},{913438523331814323877303020447676887284957839360,'dev1@127.0.0.1'},{936274486415109681974235595958868809467081785344,'dev2@127.0.0.1'},{959110449498405040071168171470060731649205731328,...},...]
2012-09-11 17:59:29.776 [warning] <0.1792.0>@riak_kv_get_fsm:prepare:164 KV {<<"_yz_schema">>,<<"_yz_default">>} preflist [] node_watcher tab: [{{by_service,yokozuna},['dev4@127.0.0.1']},{{by_service,riak_pipe},['dev4@127.0.0.1']},{{by_node,'dev4@127.0.0.1'},[yokozuna,riak_kv,riak_pipe]},{{by_service,riak_kv},['dev4@127.0.0.1']},{'dev4@127.0.0.1',63514619969}]

[engelsanchez]

We had the same problem in the verify_listkeys riak test. In our test, we have just switched from waiting on the service on that node to waiting for node watcher to know about the service in all nodes in the cluster.

[subnetmarco]

+1

[evanmcc]

What should we do here?

[rzezeski]

Not sure yet. Writing a riak test to prove/disprove it could be an issue for a user would be the first step.

[slfritchie]

Time for some belated repo curating ... is there any plan to merge this patch & have a test for Riak 2.0?

[engelsanchez]

I don't believe there is a patch for this @slfritchie

[rzezeski]

There is no patch for this and this issue no longer affects Yokozuna because it now works differently. That said, I'm fairly certain this is still something that could bite people in the future but I'm not sure it's enough of a concern to do anything about for the foreseeable future.

[jrwest]

ok, moving to milestone 2.1 for now