Skip to content

Recent writes loss in the presence of heavy handoff activity #1754

Closed
Closed
Recent writes loss in the presence of heavy handoff activity#1754

Description

@keynslug
keynslug
opened on Mar 26, 2020

Riak KV may lost recent writes in the presence of heavy handoff activity.

I've made a test with the help of Jepsen framework specifically to investigate this kind of buggy behaviour because it hit us several times already in our production environment. This test observes an occurence of this bug almost every run to be honest. An ordinary test run follows roughly these steps:

  1. Set up 5 riak kv nodes in a docker-compose environment.
  2. Join them together in a single cluster.
  3. Start pouring reads and writes over some small keyspace (10 keys was sufficient most of the time) concurrently through some small number of clients (again, 40 was sufficient), each putting as little as 1 rps. Note that this process would continue until the very end. Note also that clients take effort to ensure that writes are causally consistent (using past reads' vclocks) and performed with n = 3, r/w/pr/pw = quorum, lww = false, allow_mult = false.
  4. Give the cluster 40 seconds to stabilise. Most of the time the cluster would still have a number of ongoing transfers by this time, but that's ok.
  5. Then, set up 2 extra nodes and join them in the cluster.
  6. Again, give the cluster another 120 seconds to stabilise, after that order those 2 extra nodes to leave the cluster.
  7. Wait for them to leave cleanly. This is the most time consuming phase, but usually 200 seconds was sufficient for it to finish.
  8. Repeat the process starting from step 4, until the test run time limit passes. Usually I ran it for 15 minutes, it was enough for 3 such cycles.

I have attached a Jepsen report archive of one such test run. Most notable observations are in results.edn, here's an excerpt, redacted for brewity:

...
"jepsen638479067-6" {:valid? false,
    :configs (...),
    :final-paths ([{:op {:process 25,
                        :type :ok,
                        :f :read,
                        :value 20,
                        :index 16396,
                        :time 207095405146,
                        :vclock "a85hYGD...JZAA=="},
                    :model #knossos.model.CASRegister{:value 20}}
                    {:op {:process 25,
                        :type :ok,
                        :f :read,
                        :value 31,
                        :index 16408,
                        :time 207247072654,
                        :vclock "a85hYGD...SyAA=="},
                    :model #knossos.model.Inconsistent{:msg "can't read 31 from register 20"}}]),
    :previous-ok {...},
    :last-op {...},
    :op {...}},
...

Basically this all means that the client 25 while operating on key jepsen638479067-6 read value 20 and subsequently read value 31 quite unexpectedly, all in the absence of concurrent writes under this key.

Skimming through history.edn, here's relevant history fragment, again redacted a bit for brewity:

{:type :invoke,  :f :write,  :value 31,   :process 27,  :time 205105199455,        :index 16232}
{:type :ok,      :f :write,  :value 31,   :process 27,  :time 205110025753,  ...,  :index 16234}
{:type :invoke,  :f :write,  :value 5,    :process 26,  :time 205222111586,        :index 16245}
{:type :ok,      :f :write,  :value 5,    :process 26,  :time 205224722230,  ...,  :index 16246}
{:type :invoke,  :f :read,   :value nil,  :process 25,  :time 205256891475,        :index 16250}
{:type :ok,      :f :read,   :value 5,    :process 25,  :time 205260160969,  ...,  :index 16252}
{:type :invoke,  :f :read,   :value nil,  :process 24,  :time 206523664708,        :index 16343}
{:type :ok,      :f :read,   :value 5,    :process 24,  :time 206526735511,  ...,  :index 16344}
{:type :invoke,  :f :write,  :value 30,   :process 26,  :time 206664972077,        :index 16356}
{:type :ok,      :f :write,  :value 30,   :process 26,  :time 206673674701,  ...,  :index 16358}
{:type :invoke,  :f :write,  :value 20,   :process 27,  :time 206712230895,        :index 16361}
{:type :ok,      :f :write,  :value 20,   :process 27,  :time 206715122992,  ...,  :index 16362}
{:type :invoke,  :f :read,   :value nil,  :process 25,  :time 207091635937,        :index 16394}
{:type :ok,      :f :read,   :value 20,   :process 25,  :time 207095405146,  ...,  :index 16396}
{:type :invoke,  :f :read,   :value nil,  :process 25,  :time 207244686086,        :index 16407}
{:type :ok,      :f :read,   :value 31,   :process 25,  :time 207247072654,  ...,  :index 16408}

It can be seen clearly that an act of writing 31 at index 16232 effected read at index 16407, though in the meantime 3 subsequent writes have succeeded (16245, 16356, 16361).

Affected version(s)

riak_kv_version       : riak_kv-2.9.1.1
riak_core_version     : riak_kv-2.9.1
riak_api_version      : riak_kv-2.9.1
riak_pb_version       : riak_kv-2.9.1
riak_pipe_version     : riak_kv-2.9.1

Though it won't hurt to mention that I have successfully reproduced this bug under riak 2.2.3 as well.

Steps to reproduce

  1. Clone aforementioned repo.

  2. Start a test run with:

    $ cd system
$ docker-compose up -d
$ docker-compose exec control ./run-test

  3. Wait for it to finish cleanly.

    Note that tearing down node with riak stop on 2.9.1 may become stuck for some reason at the end of a run, simple ^C would be fine then.

  4. Look at the analysis report in store/latest/results.edn.

Suspected cause

Essentially this is caused by the fact that put fsm does not account for the possibility of multiple forwards to another coordinator. I'll try to illustrate:

  1. Node n1 receives put request and spin up a fsm to handle it.
  2. This fsm @ n1 decides to forward request to another node n2 (which happens to be in the preflist from the point of view of n1), spawns fsm there and waits for it to acknowledge their readiness, given retry_put_coordinator_failure is true which is the default per cuttlefish schema.
  3. Again, this fsm @ n2 may as I suspect under certain circumstances decide that it is in fact not in the preflist anymore, and forward request to another node n3, again ending up waiting for acknowlege afterwards. Here, possible circumstances are high vnode churn in the cluster.
  4. The fsm @ n3 happily acknowlegdes readiness to fsm @ n2 and proceeds with coordinating put operation.
  5. The fsm @ n2 receives acknowledgement and stops, without any other interaction with fsm @ n1.
  6. This fsm @ n1 times out waiting for the acknowledgement and retries forwarding request after 3 seconds by default, whereas original request is quite likely handled successfully already at this point.

This is why I believe there are occasional unrecognized messages in logs, which are extraneous responses to original requests retried unwarrantedly:

2020-03-25T19:19:00.386369Z [error] Unrecognized message {15919439,{ok,{r_object,<<"registers">>,<<"jepsen638479067-8">>,[{r_content,{dict,3,16,16,8,80,48,{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},{{[],[],[],[],[],[],[],[],[],[],[[<<"X-Riak-VTag">>,50,113,86,90,100,101,73,71,104,90,49,76,106,117,113,77,121,106,86,52,98,70]],[[<<"index">>]],[],[[<<"X-Riak-Last-Modified">>|{1585,163940,383362}]],[],[]}}},<<"37">>}],[{<<"...">>,{13,63752383125}},{<<188,169,128,137,39,255,43,155>>,{5,63752383126}},{<<188,169,128,137,39,255,44,215,0,0,0,1>>,{28,63752383133}},{<<91,17,173,142,39,242,0,107>>,{1,63752383139}},{<<187,196,68,144,40,0,3,163>>,{8,63752383140}},{<<188,169,128,137,39,255,44,166>>,{7,63752383140}}],{dict,1,16,16,8,80,48,{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},{{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[[clean|true]],[]}}},undefined}}}
2020-03-25T19:19:02.354180Z [error] Unrecognized message {53908694,{ok,{r_object,<<"registers">>,<<"jepsen638479067-8">>,[{r_content,{dict,3,16,16,8,80,48,{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},{{[],[],[],[],[],[],[],[],[],[],[[<<"X-Riak-VTag">>,49,85,73,73,113,78,109,51,122,50,116,66,102,119,90,103,55,81,100,57,76,49]],[[<<"index">>]],[],[[<<"X-Riak-Last-Modified">>|{1585,163942,349490}]],[],[]}}},<<"17">>}],[{<<"...">>,{13,63752383125}},{<<188,169,128,137,39,255,43,155>>,{5,63752383126}},{<<188,169,128,137,39,255,44,215,0,0,0,1>>,{28,63752383133}},{<<91,17,173,142,39,242,0,107>>,{1,63752383139}},{<<188,169,128,137,39,255,44,166>>,{7,63752383140}},{<<187,196,68,144,40,0,3,163>>,{11,63752383142}}],{dict,1,16,16,8,80,48,{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},{{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[[clean|true]],[]}}},undefined}}}

One more evidence which strengthen my suspicion is that turning off retry_put_coordinator_failure makes this buggy behaviuor go away with quite high probability, if not completely, given the number of test runs I've performed so far.

Additional observations

Moreover it's not clear for me why acknowledgement is being sent in the execute state of an fsm, but not in the validate state since there's a possibility that execute will be skipped altogether, in the event of parameter violation for example.

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Fields

    No fields configured for issues without a type.

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions