Skip to content

Instantly share code, notes, and snippets.

@slfritchie

slfritchie/description.txt Secret

Last active August 29, 2015 14:09
Show Gist options
  • Save slfritchie/442e09035c70c5ab6240 to your computer and use it in GitHub Desktop.
Save slfritchie/442e09035c70c5ab6240 to your computer and use it in GitHub Desktop.
Download ZIP
No, I don't know how vector clocks work............
Raw
description.txt
* All of the log messages below are from dev3's log, the node that
* was joined to the cluster and handoff to dev3 was running when
* these new updates run and their logs captured.
riak_kv_vnode:do_put(Sender, {Bucket,_Key}=BKey, RObj, ReqID, StartTime, Options, State) ->
[...]
{PrepPutRes, UpdPutArgs} = prepare_put(State, PutArgs),
{Reply, UpdState} = perform_put(PrepPutRes, State, UpdPutArgs),
riak_core_vnode:reply(Sender, Reply),
2014-11-17 20:20:33.351 [info] <0.574.0>@riak_kv_vnode:prepare_put:1084 prepare_put2: top {<<"b">>,<<"k-30">>} ... original RObj sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{18,63583442433}}] bprops [{name,<<98>>},{allow_mult,true},{basic_quorum,false},{big_vclock,50},{chash_keyfun,{riak_core_util,chash_std_keyfun}},{dw,quorum},{last_write_wins,false},{linkfun,{modfun,riak_kv_wm_link_walker,mapreduce_linkfun}},{n_val,3},{notfound_ok,true},{old_vclock,86400},{postcommit,[]},{pr,0},{precommit,[]},{pw,0},{r,quorum},{repl,true},{rw,quorum},{small_vclock,50},{w,quorum},{young_vclock,20}] coord false lww false starttime 63583442433 prunetime 63583442433 counter_op undefined
riak_kv_vnode:prepare_put(), 2nd clause
top of function, Coord=false
2014-11-17 20:20:33.351 [info] <0.574.0>@riak_kv_vnode:prepare_put:1088 prepare_put2: not_found {<<"b">>,<<"k-30">>} ... original RObj sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{18,63583442433}}]
riak_kv_vnode:prepare_put(), 2nd clause
do_get_object() returned {error, not_found, _UpdModState}
2014-11-17 20:20:33.351 [info] <0.574.0>@riak_kv_vnode:prepare_put:1096 prepare_put2: {<<"b">>,<<"k-30">>}
riak_kv_vnode:prepare_put(), 2nd clause
case GetReply of ok ->
2014-11-17 20:20:33.351 [info] <0.574.0>@riak_kv_vnode:prepare_put:1103 prepare_put2: {<<"b">>,<<"k-30">>}
riak_kv_vnode:prepare_put(), 2nd clause
just before call to prepare_new_put()
2014-11-17 20:20:33.352 [info] <0.574.0>@riak_kv_vnode:prepare_new_put:1162 prepare_new_put: VId <<157,62,8,202,84,105,217,70>> RObj {<<"b">>,<<"k-30">>} sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{18,63583442433}}]
riak_kv_vnode:prepare_new_put(false, ...)
Return the object as-is (no vclock change)
2014-11-17 20:20:33.352 [info] <0.574.0>@riak_kv_vnode:prepare_put:1105 prepare_put2: ObjToStore {<<98>>,<<107,45,51,48>>} sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{18,63583442433}}]
riak_kv_vnode:prepare_put(), 2nd clause
immediately before returning {{true, ObjToStore}, ...}
2014-11-17 20:20:33.352 [info] <0.574.0>@riak_kv_vnode:perform_put:1194 perform_put {<<"b">>,<<"k-30">>} sibs 1 Obj [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{18,63583442433}}]
--- next req ---
2014-11-17 20:20:33.360 [info] <0.574.0>@riak_kv_vnode:prepare_put:1084 prepare_put2: top {<<"b">>,<<"k-30">>} ... original RObj sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}] bprops [{name,<<98>>},{allow_mult,true},{basic_quorum,false},{big_vclock,50},{chash_keyfun,{riak_core_util,chash_std_keyfun}},{dw,quorum},{last_write_wins,false},{linkfun,{modfun,riak_kv_wm_link_walker,mapreduce_linkfun}},{n_val,3},{notfound_ok,true},{old_vclock,86400},{postcommit,[]},{pr,0},{precommit,[]},{pw,0},{r,quorum},{repl,true},{rw,quorum},{small_vclock,50},{w,quorum},{young_vclock,20}] coord false lww false starttime 63583442433 prunetime 63583442433 counter_op undefined
riak_kv_vnode:prepare_put(), 2nd clause
top of function, Coord=false
2014-11-17 20:20:33.361 [info] <0.574.0>@riak_kv_vnode:prepare_put:1091 prepare_put2: found {<<"b">>,<<"k-30">>}, TheOldObj sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{18,63583442433}}]
riak_kv_vnode:prepare_put(), 2nd clause
The object exists locally (sibling count and vclock)
2014-11-17 20:20:33.361 [info] <0.574.0>@riak_kv_vnode:prepare_put:1108 prepare_put2: OldObj {<<"b">>,<<"k-30">>} sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{18,63583442433}}]
riak_kv_vnode:prepare_put(), 2nd clause
Immediately before calling put_merge()
2014-11-17 20:20:33.361 [info] <0.574.0>@riak_kv_vnode:prepare_put:1114 prepare_put2: NewObj {<<"b">>,<<"k-30">>} sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}]
riak_kv_vnode:prepare_put(), 2nd clause
This is the result of put_merge()
2014-11-17 20:20:33.361 [info] <0.574.0>@riak_kv_vnode:prepare_put:1117 prepare_put2: AMObj {<<"b">>,<<"k-30">>} sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}]
riak_kv_vnode:prepare_put(), 2nd clause
This is the result of enforce_allow_mult()
2014-11-17 20:20:33.361 [info] <0.574.0>@riak_kv_vnode:prepare_put:1124 prepare_put2: indexspecs {<<"b">>,<<"k-30">>}
riak_kv_vnode:prepare_put(), 2nd clause
IndexSpecs is [], because we're using Bitcask, and it
doesn't support indexes.
2014-11-17 20:20:33.361 [info] <0.574.0>@riak_kv_vnode:prepare_put:1135 prepare_put2: Prune {<<"b">>,<<"k-30">>} vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}]
riak_kv_vnode:prepare_put(), 2nd clause
This is the newly-pruned vclock
2014-11-17 20:20:33.361 [info] <0.574.0>@riak_kv_vnode:prepare_put:1138 prepare_put2: set_vclock {<<"b">>,<<"k-30">>} sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}]
riak_kv_vnode:prepare_put(), 2nd clause
This is the newly-pruned vclock in the new riak_object
2014-11-17 20:20:33.362 [info] <0.574.0>@riak_kv_vnode:prepare_put:1141 prepare_put2: ObjToStore {<<"b">>,<<"k-30">>} sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}]
riak_kv_vnode:prepare_put(), 2nd clause
This is the newly-pruned vclock in the new riak_object
called ObjToStore
2014-11-17 20:20:33.362 [info] <0.574.0>@riak_kv_vnode:prepare_put:1143 prepare_put2: ObjToStore2 {<<"b">>,<<"k-30">>} sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}]
riak_kv_vnode:prepare_put(), 2nd clause
After calling handle_counter()
2014-11-17 20:20:33.362 [info] <0.574.0>@riak_kv_vnode:perform_put:1194 perform_put {<<"b">>,<<"k-30">>} sibs 1 Obj [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}]
--- next req ---
2014-11-17 20:20:33.363 [info] <0.574.0>@riak_kv_vnode:prepare_put:1084 prepare_put2: top {<<"b">>,<<"k-30">>} ... original RObj sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{18,63583442433}}] bprops [{name,<<98>>},{allow_mult,true},{basic_quorum,false},{big_vclock,50},{chash_keyfun,{riak_core_util,chash_std_keyfun}},{dw,quorum},{last_write_wins,false},{linkfun,{modfun,riak_kv_wm_link_walker,mapreduce_linkfun}},{n_val,3},{notfound_ok,true},{old_vclock,86400},{postcommit,[]},{pr,0},{precommit,[]},{pw,0},{r,quorum},{repl,true},{rw,quorum},{small_vclock,50},{w,quorum},{young_vclock,20}] coord true lww false starttime 63583442433 prunetime 63583442433 counter_op undefined
riak_kv_vnode:prepare_put(), 2nd clause
top of function, Coord=**true**
Also, notice that this vclock is stale: the last op just
finished writing
[{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}]
but the (intentionally broken client) has given us an older vclock.
2014-11-17 20:20:33.364 [info] <0.574.0>@riak_kv_vnode:prepare_put:1091 prepare_put2: found {<<"b">>,<<"k-30">>}, TheOldObj sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}]
riak_kv_vnode:prepare_put(), 2nd clause
The object exists locally (sibling count and vclock)
2014-11-17 20:20:33.364 [info] <0.574.0>@riak_kv_vnode:prepare_put:1108 prepare_put2: OldObj {<<"b">>,<<"k-30">>} sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}]
riak_kv_vnode:prepare_put(), 2nd clause
Immediately before calling put_merge()
2014-11-17 20:20:33.364 [info] <0.574.0>@riak_kv_vnode:prepare_put:1114 prepare_put2: NewObj {<<"b">>,<<"k-30">>} sibs 2 vclock [{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}]
riak_kv_vnode:prepare_put(), 2nd clause
This is the result of put_merge(), a newobj flavor
FIRST APPEARANCE of the actor <<157,62,8,202,84,105,217,70>>
which is this vnode's actor ID.
Note that the actor count is 2, interesting, why not 1?
The caller uses:
case put_merge(Coord, LWW, OldObj, RObj, VId, StartTime) of
Hrm, we know the LWW is false, so the 2nd arg to put_merge()
is false. We also know that Coord is true. So, that leaves
us with:
put_merge(Coord=true, LWW=false, CurObj, UpdObj, VId, StartTime) ->
UpdObj1 = riak_object:increment_vclock(UpdObj, VId, StartTime),
%% SLF: VId doesn't appear in UpdObj's vclock
%% before the call, so it must be added here.
UpdVC = riak_object:vclock(UpdObj1),
CurVC = riak_object:vclock(CurObj),
%% Check the coord put will replace the existing object
case vclock:get_counter(VId, UpdVC) > vclock:get_counter(VId, CurVC) andalso
vclock:descends(CurVC, UpdVC) == false andalso
vclock:descends(UpdVC, CurVC) == true of
true ->
{newobj, UpdObj1};
false ->
%% If not, make sure it does
%% SLF: here is where we get our
%% second actor count *and* the source
%% of the 2 siblings.
{newobj, riak_object:increment_vclock(
riak_object:merge(CurObj, UpdObj1), VId, StartTime)}
end.
2014-11-17 20:20:33.364 [info] <0.574.0>@riak_kv_vnode:prepare_put:1117 prepare_put2: AMObj {<<"b">>,<<"k-30">>} sibs 2 vclock [{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}]
riak_kv_vnode:prepare_put(), 2nd clause
This is the result of enforce_allow_mult()
2014-11-17 20:20:33.364 [info] <0.574.0>@riak_kv_vnode:prepare_put:1124 prepare_put2: indexspecs {<<"b">>,<<"k-30">>}
2014-11-17 20:20:33.364 [info] <0.574.0>@riak_kv_vnode:prepare_put:1135 prepare_put2: Prune {<<"b">>,<<"k-30">>} vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}]
2014-11-17 20:20:33.365 [info] <0.574.0>@riak_kv_vnode:prepare_put:1138 prepare_put2: set_vclock {<<"b">>,<<"k-30">>} sibs 2 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}]
2014-11-17 20:20:33.365 [info] <0.574.0>@riak_kv_vnode:prepare_put:1141 prepare_put2: ObjToStore {<<"b">>,<<"k-30">>} sibs 2 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}]
2014-11-17 20:20:33.365 [info] <0.574.0>@riak_kv_vnode:prepare_put:1143 prepare_put2: ObjToStore2 {<<"b">>,<<"k-30">>} sibs 2 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}]
No changes to the object here
2014-11-17 20:20:33.365 [info] <0.574.0>@riak_kv_vnode:perform_put:1194 perform_put {<<"b">>,<<"k-30">>} sibs 2 Obj [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}]
2014-11-17 20:20:33.365 [warning] <0.574.0>@riak_kv_vnode:encode_and_put:1838 Too many siblings for object <<"b">>/<<"k-30">> (2)
--- next req ---
NOTE: The passage of time: we're now into the script's serialized writing phase
with only one client.
NOTE: The coordinator is *never* true for the next 15 updates. That
means that some other vnode (on dev1 or dev2) is the coordinator.
NOTE: The incoming vclock never contains dev3's/our vnode actor ID,
<<157,62,8,202,84,105,217,70>>.
NOTE: But we always find out vnode actor ID,
<<157,62,8,202,84,105,217,70>>, in the local store, because of
the single time that we were the coordinator.
2014-11-17 20:20:41.971 [info] <0.574.0>@riak_kv_vnode:prepare_put:1084 prepare_put2: top {<<"b">>,<<"k-30">>} ... original RObj sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{4,63583442433}},{<<197,82,177,11,84,105,217,70>>,{20,63583442441}}] bprops [{name,<<98>>},{allow_mult,true},{basic_quorum,false},{big_vclock,50},{chash_keyfun,{riak_core_util,chash_std_keyfun}},{dw,quorum},{last_write_wins,false},{linkfun,{modfun,riak_kv_wm_link_walker,mapreduce_linkfun}},{n_val,3},{notfound_ok,true},{old_vclock,86400},{postcommit,[]},{pr,0},{precommit,[]},{pw,0},{r,quorum},{repl,true},{rw,quorum},{small_vclock,50},{w,quorum},{young_vclock,20}] coord false lww false starttime 63583442441 prunetime 63583442441 counter_op undefined
2014-11-17 20:20:41.971 [info] <0.574.0>@riak_kv_vnode:prepare_put:1091 prepare_put2: found {<<"b">>,<<"k-30">>}, TheOldObj sibs 2 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}]
2014-11-17 20:20:41.974 [info] <0.574.0>@riak_kv_vnode:perform_put:1194 perform_put {<<"b">>,<<"k-30">>} sibs 3 Obj [{<<92,176,215,10,84,105,217,80>>,{4,63583442433}},{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<197,82,177,11,84,105,217,70>>,{20,63583442441}}]
2014-11-17 20:20:41.974 [warning] <0.574.0>@riak_kv_vnode:encode_and_put:1838 Too many siblings for object <<"b">>/<<"k-30">> (3)
--- next req ---
2014-11-17 20:20:41.979 [info] <0.574.0>@riak_kv_vnode:prepare_put:1084 prepare_put2: top {<<"b">>,<<"k-30">>} ... original RObj sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{4,63583442433}},{<<197,82,177,11,84,105,217,70>>,{21,63583442441}}] bprops [{name,<<98>>},{allow_mult,true},{basic_quorum,false},{big_vclock,50},{chash_keyfun,{riak_core_util,chash_std_keyfun}},{dw,quorum},{last_write_wins,false},{linkfun,{modfun,riak_kv_wm_link_walker,mapreduce_linkfun}},{n_val,3},{notfound_ok,true},{old_vclock,86400},{postcommit,[]},{pr,0},{precommit,[]},{pw,0},{r,quorum},{repl,true},{rw,quorum},{small_vclock,50},{w,quorum},{young_vclock,20}] coord false lww false starttime 63583442441 prunetime 63583442441 counter_op undefined
2014-11-17 20:20:41.980 [info] <0.574.0>@riak_kv_vnode:prepare_put:1091 prepare_put2: found {<<"b">>,<<"k-30">>}, TheOldObj sibs 3 vclock [{<<92,176,215,10,84,105,217,80>>,{4,63583442433}},{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<197,82,177,11,84,105,217,70>>,{20,63583442441}}]
2014-11-17 20:20:41.981 [info] <0.574.0>@riak_kv_vnode:perform_put:1194 perform_put {<<"b">>,<<"k-30">>} sibs 4 Obj [{<<92,176,215,10,84,105,217,80>>,{4,63583442433}},{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<197,82,177,11,84,105,217,70>>,{21,63583442441}}]
2014-11-17 20:20:41.981 [warning] <0.574.0>@riak_kv_vnode:encode_and_put:1838 Too many siblings for object <<"b">>/<<"k-30">> (4)
--- next req ---
2014-11-17 20:20:41.986 [info] <0.574.0>@riak_kv_vnode:prepare_put:1084 prepare_put2: top {<<"b">>,<<"k-30">>} ... original RObj sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{4,63583442433}},{<<197,82,177,11,84,105,217,70>>,{22,63583442441}}] bprops [{name,<<98>>},{allow_mult,true},{basic_quorum,false},{big_vclock,50},{chash_keyfun,{riak_core_util,chash_std_keyfun}},{dw,quorum},{last_write_wins,false},{linkfun,{modfun,riak_kv_wm_link_walker,mapreduce_linkfun}},{n_val,3},{notfound_ok,true},{old_vclock,86400},{postcommit,[]},{pr,0},{precommit,[]},{pw,0},{r,quorum},{repl,true},{rw,quorum},{small_vclock,50},{w,quorum},{young_vclock,20}] coord false lww false starttime 63583442441 prunetime 63583442441 counter_op undefined
2014-11-17 20:20:41.986 [info] <0.574.0>@riak_kv_vnode:prepare_put:1091 prepare_put2: found {<<"b">>,<<"k-30">>}, TheOldObj sibs 4 vclock [{<<92,176,215,10,84,105,217,80>>,{4,63583442433}},{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<197,82,177,11,84,105,217,70>>,{21,63583442441}}]
2014-11-17 20:20:41.988 [info] <0.574.0>@riak_kv_vnode:perform_put:1194 perform_put {<<"b">>,<<"k-30">>} sibs 5 Obj [{<<92,176,215,10,84,105,217,80>>,{4,63583442433}},{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<197,82,177,11,84,105,217,70>>,{22,63583442441}}]
2014-11-17 20:20:41.988 [warning] <0.574.0>@riak_kv_vnode:encode_and_put:1838 Too many siblings for object <<"b">>/<<"k-30">> (5)
--- next req ---
[... time elapses...]
--- next req ---
2014-11-17 20:20:42.080 [info] <0.574.0>@riak_kv_vnode:prepare_put:1084 prepare_put2: top {<<"b">>,<<"k-30">>} ... original RObj sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{4,63583442433}},{<<197,82,177,11,84,105,217,70>>,{34,63583442442}}] bprops [{name,<<98>>},{allow_mult,true},{basic_quorum,false},{big_vclock,50},{chash_keyfun,{riak_core_util,chash_std_keyfun}},{dw,quorum},{last_write_wins,false},{linkfun,{modfun,riak_kv_wm_link_walker,mapreduce_linkfun}},{n_val,3},{notfound_ok,true},{old_vclock,86400},{postcommit,[]},{pr,0},{precommit,[]},{pw,0},{r,quorum},{repl,true},{rw,quorum},{small_vclock,50},{w,quorum},{young_vclock,20}] coord false lww false starttime 63583442442 prunetime 63583442442 counter_op undefined
2014-11-17 20:20:42.081 [info] <0.574.0>@riak_kv_vnode:prepare_put:1091 prepare_put2: found {<<"b">>,<<"k-30">>}, TheOldObj sibs 16 vclock [{<<92,176,215,10,84,105,217,80>>,{4,63583442433}},{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<197,82,177,11,84,105,217,70>>,{33,63583442442}}]
TheOldObj : [{<<92,176,215,10,84,105,217,80>>,{4,63583442433}},{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<197,82,177,11,84,105,217,70>>,{33,63583442442}}]
: sibs=16
incoming RObj : [{<<92,176,215,10,84,105,217,80>>,{4,63583442433}}, {<<197,82,177,11,84,105,217,70>>,{34,63583442442}}]
: sibs=1
Coord=false, LWW=false, local actor ID=<<157,62,8,...>>
local vnode put: [{<<92,176,215,10,84,105,217,80>>,{4,63583442433}},{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<197,82,177,11,84,105,217,70>>,{34,63583442442}}]
: sibs=17
2014-11-17 20:20:42.082 [info] <0.574.0>@riak_kv_vnode:prepare_put:1143 prepare_put2: ObjToStore2 {<<"b">>,<<"k-30">>} sibs 17 vclock [{<<92,176,215,10,84,105,217,80>>,{4,63583442433}},{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<197,82,177,11,84,105,217,70>>,{34,63583442442}}]
2014-11-17 20:20:42.083 [info] <0.574.0>@riak_kv_vnode:perform_put:1194 perform_put {<<"b">>,<<"k-30">>} sibs 17 Obj [{<<92,176,215,10,84,105,217,80>>,{4,63583442433}},{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<197,82,177,11,84,105,217,70>>,{34,63583442442}}]
2014-11-17 20:20:42.083 [warning] <0.574.0>@riak_kv_vnode:encode_and_put:1838 Too many siblings for object <<"b">>/<<"k-30">> (17)
Raw
spammy.patch
diff --git a/src/riak_kv_vnode.erl b/src/riak_kv_vnode.erl
index b86cbbc..093d7bc 100644
--- a/src/riak_kv_vnode.erl
+++ b/src/riak_kv_vnode.erl
@@ -867,6 +872,10 @@ handoff_finished(_TargetNode, State) ->
handle_handoff_data(BinObj, State) ->
try
{BKey, Val} = decode_binary_object(BinObj),
+{B, K} = BKey,
+O = riak_object:from_binary(B, K, Val),
+VClock = riak_object:vclock(O),
+lager:info("handoff receiver ~p sibs ~w vclock ~p\n", [BKey, length(riak_object:get_contents(O)), VClock]),
{B, K} = BKey,
case do_diffobj_put(BKey, riak_object:from_binary(B, K, Val),
State) of
@@ -1055,8 +1064,10 @@ prepare_put(State=#state{vnodeid=VId,
ObjToStore =
case Coord of
true ->
+lager:info("prepare_put1: increment_vclock ~p\n", [{Bucket, _Key}]),
riak_object:increment_vclock(RObj, VId, StartTime);
false ->
+lager:info("prepare_put1: ~p\n", [{Bucket, _Key}]),
RObj
end,
{{true, ObjToStore}, PutArgs#putargs{is_index = false}};
@@ -1075,47 +1086,66 @@ prepare_put(#state{vnodeid=VId,
prunetime=PruneTime,
counter_op = CounterOp},
IndexBackend) ->
+lager:info("prepare_put2: top ~p ... original RObj sibs ~w vclock ~w bprops ~w coord ~w lww ~w starttime ~w prunetime ~w counter_op ~w\n", [{Bucket, Key}, length(riak_object:get_contents(RObj)), riak_object:vclock(RObj), BProps, Coord, LWW, StartTime, PruneTime, CounterOp]),
GetReply =
case do_get_object(Bucket, Key, Mod, ModState) of
{error, not_found, _UpdModState} ->
+lager:info("prepare_put2: not_found ~p ... original RObj sibs ~w vclock ~w\n", [{Bucket, Key}, length(riak_object:get_contents(RObj)), riak_object:vclock(RObj)]),
ok;
{ok, TheOldObj, _UpdModState} ->
+lager:info("prepare_put2: found ~p, TheOldObj sibs ~w vclock ~w\n", [{Bucket, Key}, length(riak_object:get_contents(TheOldObj)), riak_object:vclock(TheOldObj)]),
{ok, TheOldObj}
end,
case GetReply of
ok ->
+lager:info("prepare_put2: ~p\n", [{Bucket, Key}]),
case IndexBackend of
true ->
IndexSpecs = riak_object:index_specs(RObj);
false ->
IndexSpecs = []
end,
+lager:info("prepare_put2: ~p\n", [{Bucket, Key}]),
ObjToStore = prepare_new_put(Coord, RObj, VId, StartTime, CounterOp),
+lager:info("prepare_put2: ObjToStore ~w sibs ~w vclock ~w\n", [{Bucket, Key}, length(riak_object:get_contents(ObjToStore)), riak_object:vclock(ObjToStore)]),
{{true, ObjToStore}, PutArgs#putargs{index_specs=IndexSpecs, is_index=IndexBackend}};
{ok, OldObj} ->
+lager:info("prepare_put2: OldObj ~p sibs ~w vclock ~w\n", [{Bucket, Key}, length(riak_object:get_contents(OldObj)), riak_object:vclock(OldObj)]),
case put_merge(Coord, LWW, OldObj, RObj, VId, StartTime) of
{oldobj, OldObj1} ->
+lager:info("prepare_put2: OldObj1 ~p sibs ~w vclock ~w\n", [{Bucket, Key}, length(riak_object:get_contents(OldObj1)), riak_object:vclock(OldObj1)]),
{{false, OldObj1}, PutArgs};
{newobj, NewObj} ->
+lager:info("prepare_put2: NewObj ~p sibs ~w vclock ~w\n", [{Bucket, Key}, length(riak_object:get_contents(NewObj)), riak_object:vclock(NewObj)]),
VC = riak_object:vclock(NewObj),
AMObj = enforce_allow_mult(NewObj, BProps),
+lager:info("prepare_put2: AMObj ~p sibs ~w vclock ~w\n", [{Bucket, Key}, length(riak_object:get_contents(AMObj)), riak_object:vclock(AMObj)]),
IndexSpecs = case IndexBackend of
true ->
+lager:info("prepare_put2: indexspecs ~p\n", [{Bucket, Key}]),
riak_object:diff_index_specs(AMObj,
OldObj);
false ->
+lager:info("prepare_put2: indexspecs ~p\n", [{Bucket, Key}]),
[]
end,
ObjToStore = case PruneTime of
undefined ->
+lager:info("prepare_put2: prune ~p\n", [{Bucket, Key}]),
AMObj;
_ ->
- riak_object:set_vclock(AMObj,
- vclock:prune(VC,
+ Prune = vclock:prune(VC,
PruneTime,
- BProps))
+ BProps),
+lager:info("prepare_put2: Prune ~p vclock ~w\n", [{Bucket, Key}, Prune]),
+ XX = riak_object:set_vclock(AMObj,
+ Prune),
+lager:info("prepare_put2: set_vclock ~p sibs ~w vclock ~w\n", [{Bucket, Key}, length(riak_object:get_contents(XX)), riak_object:vclock(XX)]),
+ XX
end,
+lager:info("prepare_put2: ObjToStore ~p sibs ~w vclock ~w\n", [{Bucket, Key}, length(riak_object:get_contents(ObjToStore)), riak_object:vclock(ObjToStore)]),
ObjToStore2 = handle_counter(Coord, CounterOp, VId, ObjToStore),
+lager:info("prepare_put2: ObjToStore2 ~p sibs ~w vclock ~w\n", [{Bucket, Key}, length(riak_object:get_contents(ObjToStore2)), riak_object:vclock(ObjToStore2)]),
{{true, ObjToStore2},
PutArgs#putargs{index_specs=IndexSpecs, is_index=IndexBackend}}
end
@@ -1124,13 +1154,17 @@ prepare_put(#state{vnodeid=VId,
%% @Doc in the case that this a co-ordinating put, prepare the object.
prepare_new_put(true, RObj, VId, StartTime, CounterOp) when is_integer(CounterOp) ->
VClockUp = riak_object:increment_vclock(RObj, VId, StartTime),
+lager:info("prepare_new_put: VId ~p RObj ~p sibs ~w vclock ~w\n", [VId, {riak_object:bucket(RObj), riak_object:key(RObj)}, length(riak_object:get_contents(RObj)), VClockUp]),
%% coordinating a _NEW_ counter operation means
%% creating + incrementing the counter.
%% Make a new counter, stuff it in the riak_object
riak_kv_counter:update(VClockUp, VId, CounterOp);
prepare_new_put(true, RObj, VId, StartTime, _CounterOp) ->
- riak_object:increment_vclock(RObj, VId, StartTime);
+ XX = riak_object:increment_vclock(RObj, VId, StartTime),
+lager:info("prepare_new_put: VId ~p RObj ~p sibs ~w vclock ~w\n", [VId, {riak_object:bucket(RObj), riak_object:key(RObj)}, length(riak_object:get_contents(XX)), riak_object:vclock(XX)]),
+ XX;
prepare_new_put(false, RObj, _VId, _StartTime, _CounterOp) ->
+lager:info("prepare_new_put: VId ~p RObj ~p sibs ~w vclock ~w\n", [_VId, {riak_object:bucket(RObj), riak_object:key(RObj)}, length(riak_object:get_contents(RObj)), riak_object:vclock(RObj)]),
RObj.
handle_counter(true, CounterOp, VId, RObj) when is_integer(CounterOp) ->
@@ -1161,6 +1195,8 @@ perform_put({true, Obj},
bkey={Bucket, Key},
reqid=ReqID,
index_specs=IndexSpecs}) ->
+ObjVClock = riak_object:vclock(Obj),
+lager:info("perform_put ~p sibs ~w Obj ~w\n", [{Bucket, Key}, length(riak_object:get_contents(Obj)), ObjVClock]),
case encode_and_put(Obj, Mod, Bucket, Key, IndexSpecs, ModState,
do_max_check) of
{{ok, UpdModState}, _EncodedVal} ->
@@ -1504,6 +1540,8 @@ do_diffobj_put({Bucket, Key}, DiffObj,
false ->
IndexSpecs = []
end,
+DiffObjVClock = riak_object:vclock(DiffObj),
+lager:info("do_diffobj_put ~p sibs ~w not_found ~p\n", [{Bucket, Key}, length(riak_object:get_contents(DiffObj)), DiffObjVClock]),
case encode_and_put(DiffObj, Mod, Bucket, Key,
IndexSpecs, ModState, no_max_check) of
{{ok, _UpdModState} = InnerRes, _EncodedVal} ->
@@ -1515,13 +1553,19 @@ do_diffobj_put({Bucket, Key}, DiffObj,
InnerRes
end;
{ok, OldObj, _UpdModState} ->
+OldObjVClock = riak_object:vclock(OldObj),
+lager:info("do_diffobj_put ~p sibs ~w OldObj vclock ~p\n", [{Bucket, Key}, length(riak_object:get_contents(OldObj)), OldObjVClock]),
%% Merge handoff values with the current - possibly discarding
%% if out of date. Ok to set VId/Starttime undefined as
%% they are not used for non-coordinating puts.
case put_merge(false, false, OldObj, DiffObj, undefined, undefined) of
{oldobj, _} ->
+OldObjVClock = riak_object:vclock(OldObj),
+lager:info("do_diffobj_put ~p sibs ~w put_merge oldobj\n", [{Bucket, Key}, length(riak_object:get_contents(OldObj))]),
{ok, ModState};
{newobj, NewObj} ->
+NewObjVClock = riak_object:vclock(NewObj),
+lager:info("do_diffobj_put ~p sibs ~w OldObj put_merge ~p\n", [{Bucket, Key}, length(riak_object:get_contents(NewObj)), NewObjVClock]),
AMObj = enforce_allow_mult(NewObj, riak_core_bucket:get_bucket(Bucket)),
case IndexBackend of
true ->
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment