rqlited does not load

[omerkorenn]

Hi,
I preloaded a single node of rqlited (created a 1.5gb rafb.db file).
After gracefully shutdown of the process i tried to reload it, but the process ends with "set peer timeout expired" before all the data is being loaded to memory.

Please advise,

Thanks !!!

See the log here:
sudo ./rqlited --http 0.0.0.0:4001 ./node1

        _ _ _           _
       | (_) |         | |

_ __ __ | || |_ ___ | |
| '/ _ | | | / _ / _ | The lightweight, distributed
| | | (| | | | || __/ (| | relational database.
|| _, |||___|_,|
| |
|_|

[rqlited] 2017/01/16 16:22:49 rqlited starting, version v3.9.2, commit 46589e9, branch master
[store] 2017/01/16 16:22:49 SQLite in-memory database opened
[store] 2017/01/16 16:22:49 enabling single-node mode
[tcp] 2017/01/16 16:22:49 mux serving on 127.0.0.1:4002, advertising 127.0.0.1:4002
[cluster] 2017/01/16 16:22:49 service listening on 127.0.0.1:4002
2017/01/16 16:22:49 [INFO] raft: Node at 127.0.0.1:4002 [Follower] entering Follower state (Leader: "")
[rqlited] 2017/01/16 16:22:50 failed to set peer for 127.0.0.1:4002 to 0.0.0.0:4001: no leader available (retrying)
2017/01/16 16:22:50 [WARN] raft: Heartbeat timeout from "" reached, starting election
2017/01/16 16:22:50 [INFO] raft: Node at 127.0.0.1:4002 [Candidate] entering Candidate state
2017/01/16 16:22:50 [DEBUG] raft: Votes needed: 1
2017/01/16 16:22:50 [DEBUG] raft: Vote granted from 127.0.0.1:4002. Tally: 1
2017/01/16 16:22:50 [INFO] raft: Election won. Tally: 1
2017/01/16 16:22:50 [INFO] raft: Node at 127.0.0.1:4002 [Leader] entering Leader state
2017/01/16 16:22:50 [DEBUG] raft: Node 127.0.0.1:4002 updated peer set (2): [127.0.0.1:4002]
2017/01/16 16:22:50 [DEBUG] raft: Node 127.0.0.1:4002 updated peer set (2): [127.0.0.1:4002]
2017/01/16 16:22:50 [DEBUG] raft: Node 127.0.0.1:4002 updated peer set (2): [127.0.0.1:4002]
[cluster] 2017/01/16 16:23:01 received connection from 127.0.0.1:45257
[rqlited] 2017/01/16 16:23:11 failed to set peer for 127.0.0.1:4002 to 0.0.0.0:4001: timed out enqueuing operation (retrying)
[cluster] 2017/01/16 16:23:21 received connection from 127.0.0.1:45258
[rqlited] 2017/01/16 16:23:31 failed to set peer for 127.0.0.1:4002 to 0.0.0.0:4001: timed out enqueuing operation (retrying)
[rqlited] 2017/01/16 16:23:31 failed to set peer for localhost:4002 to 0.0.0.0:4001: set peer timeout expired

[otoolep]

Thanks for the report @omerkorenn -- I will take a look.

[otoolep]

@omerkorenn -- did you load the your node via this technique?

https://github.com/rqlite/rqlite/blob/master/doc/RESTORE_FROM_SQLITE.md

[otoolep]

If you are loading from a SQLite dump, I would guess you're hitting the 10-second timeout at this line of code:

https://github.com/rqlite/rqlite/blob/master/store/store.go#L441

I can make this configurable, so you can increase it.

[otoolep]

@omerkorenn -- can you build top of tree, as per these instructions:

https://github.com/rqlite/rqlite/blob/master/CONTRIBUTING.md#building-rqlite

If so, please launch rqlite with a larger timeout like so:

rqlited -raftapplytimeout 30s 

30 seconds is a suggestion, you might need to go higher. I'd be interested in knowing what value you need. v3.9.2 has a 10 second timeout.

[otoolep]

OK, I'm going to assume this is solved.

[omerkorenn]

Hi,

Sorry for the late response.

The timeout is indeed the problem.
It is hard to know how much time is needed to load the data.
It really machine/dataset dependent, anyway i aim to use a ~32GB dataset.

Do you think it is possible to overcome the problem by trying to connect to the raft after loading the data instead of in parallel ?

[otoolep]

Did you try any increasing the timeout at all?

[omerkorenn]

Yeah sure, it worked with 120s

[otoolep]

OK, 120s is kinda long. I don't follow your suggestion about "parallel". Can you explain more?

You could split the file you're loading into multiple smaller files, which will help you keep your timeout setting low.

[omerkorenn]

Thanks i'll try this.

I saw that the store.open(..)
https://github.com/rqlite/rqlite/blob/master/cmd/rqlited/main.go#L176
returns before loading all data to memory, and publishAPIAddr is being called after this
https://github.com/rqlite/rqlite/blob/master/cmd/rqlited/main.go#L216
causing the process to fail after certain timeout.

So i thought maybe it is possible some how to wait the store to be ready before calling publishAPIAddr.

But i'm not sure about it

[otoolep]

Interesting @omerkorenn -- you might be onto something there, though I would need to confirm that Open doesn't block until all Raft log messages have been applied.

Let me re-open to investigate.

[otoolep]

@omerkorenn -- I have confirmed that NewRaft does return before all the log entries have been applied. I'm trying to see if there is a way to allow it to block instead.

[otoolep]

@omerkorenn -- top of tree solves this problem correctly. It waits, by default, up to 120 seconds for the initial state to be applied. You no longer need to set -raftapplytimeout. If 120 seconds is not sufficiently long, you can increase it.