Nodes in cluster die with the error : Unable to unmarshal proposal

[bhuthesh]

I'm running a cluster using binary built from master (commit 07abc9a).

After starting bulkloading with dgraphloader , I get many retry errors of the form Retrying req: 59. Error: rpc error: code = Unknown desc = failed to apply mutations error: internal error: context deadline exceeded

I think the mutations are timing out due to some nodes dying.

The last log before a node dies is
RECEIVED: MsgApp
SENDING: MsgAppResp
Unable to unmarshal proposal: [8 161 214 170 many many lines (of binary protocol?) 119 51 46 111] %!q(MISSING)
EDIT : Tagging @janardhan1993

[bhuthesh]

Hi @janardhan1993, any timeline on when the v0.8 will be released?

[janardhan1993]

We started using slicepool for proposals in master. We were returning the slice back to the pool after the proposal in applied in memory. But the raft memory storage keeps the entries in memory and these are sent to the replicas. We should be returning the slice only after the corresponding entry is compacted.(after snapshot).

@bhuthesh : Can you please try with bugs/github_issues branch and let us know if it fixes your issue.

[srh]

I get a similar thing. It happens if I make a 3-node cluster, shut down one node, load a bunch of data, then reconnect the node. Possibly also requires making an additional mutation query to trigger, I haven't narrowed that down yet.

2017/07/11 23:12:09 draft.go:590: Unable to unmarshal proposal: unexpected EOF "\b\xa9\xf8\xee\x9f\x03\x12\xe2\xc7\x04\b\x01\x122\tw\f\x02\x00\x00\x00\x00\x00\x12\x04name\x1a\x1bHinkle's Employee Singer #2 \t:\x02en\x12\x1c\tw\f\x02\x00\x00\x00\x00\x00\x12\v_predicate_\x1a\x04name\x12\x1c\t\x12Mv\n\xd351h\x12\bstarring)x\f\x02\x00\x00\x00\x00\x00\x12 \t\x12Mv\n\xd351h\x12\v_predicate_\x1a\bstarring\x12$\tx\f\x02\x00\x00\x00\x00\x00\x12\x10performance.film)\x12Mv\n\xd351h\x12(\t"

[srh]

Doesn't require an additional mutation query, and I can also reproduce it in bugs/github_issues.

Here's the basic steps I used:

cd ~
mkdir blah
cd blah
echo 'default: fp % 1 + 1' > groups.conf
mkdir svr{1..3}

# Start node 1
~/go/bin/dgraph --group_conf ~/blah/groups.conf --groups "0,1" \
  --idx 1 --port_offset 0 --my "127.0.0.1:12345" --debugmode=true \
  --p ~/blah/svr1/p --w ~/blah/svr1/w > ~/blah/svr1/dgraph.log 2>&1 &

# Start node 2
~/go/bin/dgraph --group_conf ~/blah/groups.conf --groups "0,1" --idx 2 \
  --port_offset 1 --my "127.0.0.1:12346" --peer "127.0.0.1:12345" \
  --debugmode=true --p ~/blah/svr2/p --w ~/blah/svr2/w \
  > ~/blah/svr2/dgraph.log 2>&1 &

# Start node 3
~/go/bin/dgraph --group_conf ~/blah/groups.conf --groups "0,1" --idx 3 \
  --port_offset 2 --my "127.0.0.1:12347" --peer "127.0.0.1:12346" \
  --debugmode=true --p ~/blah/svr3/p --w ~/blah/svr3/w \
  > ~/blah/svr3/dgraph.log 2>&1 &

# Kill node 3
kill %3

# Load data (from benchmarks repo)
cd ~/benchmarks
~/go/bin/dgraphloader -r ~/1million.rdf.gz -s data/21million.schema 

# When that finishes, revive node 3
cd ~/blah
~/go/bin/dgraph --group_conf ~/blah/groups.conf --groups "0,1" --idx 3 \
  --port_offset 2 --my "127.0.0.1:12347" --peer "127.0.0.1:12346" \
  --debugmode=true --p ~/blah/svr3/p --w ~/blah/svr3/w \
  > ~/blah/svr3/dgraph.log 2>&1 &

I'll note that I didn't run this as a script, there was some reasonable human waiting time between commands.

Edit: Since I'm reproducing it, I'll go and try to bisect the error.

[srh]

This is going to be fixed with the latest update to #1176.

[bhuthesh]

@janardhan1993 Since it is reproducible in bugs/github_issues as mentioned my @srh, shall I wait for more fixes before I test it again?

[janardhan1993]

@bhuthesh you can try now. i forgot to push the changes to the branch. The fix is there now.

[bhuthesh]

@janardhan1993 was able to run 22 servers and index some 50M RDFs without losing any nodes. Seems the issue has been fixed in bugs/github_issues

[janardhan1993]

Fix merged to master