I am trying to run the basic usage example code from the go-liftbridge. However, if the stream leader
of a newly created stream is not the first one in the address list then I got the following error when calling client.Subscribe()
:
panic: rpc error: code = FailedPrecondition desc = Server not stream leader
Is this a bug or did I made a mistake while setting up my cluster?
In depth:
In my network, dev.lan
resolves to the IP of my development PC.
I have a three-node Liftbridge cluster.
Starting the Nats server:
$ nats-server
[4657] 2019/08/14 13:33:08.433251 [INF] Starting nats-server version 2.0.2
[4657] 2019/08/14 13:33:08.433286 [INF] Git commit [not set]
[4657] 2019/08/14 13:33:08.433388 [INF] Listening for client connections on 0.0.0.0:4222
[4657] 2019/08/14 13:33:08.433468 [INF] Server id is NDAGJBAAD4KN3J7ZNVMPT7HJSCGSOCX3YFKG765PCNHUJ6BXOK3HBQRB
[4657] 2019/08/14 13:33:08.433471 [INF] Server is ready
My liftbridge.conf
file:
listen: 0.0.0.0:9292
log.level: debug
nats {
servers: ["dev.lan:4222"]
}
clustering {
raft.logging: true
}
The peers of the Liftbridge cluster are running inside Docker containers. I built the Docker image from the latest version of Liftbridge, 2612491 with the following command:
DOCKER_BUILDKIT=1 docker build -t liftbridge:latest .
Starting the first peer:
$ docker run -it -p "9292:9292" --mount type=bind,source=liftbridge.conf,target=/liftbridge.conf liftbridge:latest --config /liftbridge.conf
INFO[2019-08-14 13:34:52] Server ID: fp8btGxtuxbqn5LZl64AEf
INFO[2019-08-14 13:34:52] Namespace: liftbridge-default
INFO[2019-08-14 13:34:52] Retention Policy: [Age: 1 week, Compact: false]
INFO[2019-08-14 13:34:52] Starting server on 0.0.0.0:9292...
INFO[2019-08-14 13:34:52] raft: Initial configuration (index=0): []
DEBU[2019-08-14 13:34:52] Attempting to join metadata Raft group...
INFO[2019-08-14 13:34:52] raft: Node at fp8btGxtuxbqn5LZl64AEf [Follower] entering Follower state (Leader: "")
DEBU[2019-08-14 13:34:52] raft-net: fp8btGxtuxbqn5LZl64AEf accepted connection from: RDEU1MVK78fAFhqDoGrvnr
WARN[2019-08-14 13:34:52] raft: Failed to get previous log: 4 log not found (last: 0)
DEBU[2019-08-14 13:34:53] raft-net: fp8btGxtuxbqn5LZl64AEf accepted connection from: RDEU1MVK78fAFhqDoGrvnr
Second peer, also this is the (Raft) leader:
$ docker run -it -p "9293:9292" --mount type=bind,source=liftbridge.conf,target=/liftbridge.conf liftbridge:latest --raft-bootstrap-seed --config /liftbridge.conf
INFO[2019-08-14 13:34:46] Server ID: RDEU1MVK78fAFhqDoGrvnr
INFO[2019-08-14 13:34:46] Namespace: liftbridge-default
INFO[2019-08-14 13:34:46] Retention Policy: [Age: 1 week, Compact: false]
INFO[2019-08-14 13:34:46] Starting server on 0.0.0.0:9292...
INFO[2019-08-14 13:34:46] raft: Initial configuration (index=0): []
DEBU[2019-08-14 13:34:46] Bootstrapping metadata Raft group as seed node
INFO[2019-08-14 13:34:46] raft: Node at RDEU1MVK78fAFhqDoGrvnr [Follower] entering Follower state (Leader: "")
WARN[2019-08-14 13:34:47] raft: Heartbeat timeout from "" reached, starting election
INFO[2019-08-14 13:34:47] raft: Node at RDEU1MVK78fAFhqDoGrvnr [Candidate] entering Candidate state in term 2
DEBU[2019-08-14 13:34:47] raft: Votes needed: 1
DEBU[2019-08-14 13:34:47] raft: Vote granted from RDEU1MVK78fAFhqDoGrvnr in term 2. Tally: 1
INFO[2019-08-14 13:34:47] raft: Election won. Tally: 1
INFO[2019-08-14 13:34:47] raft: Node at RDEU1MVK78fAFhqDoGrvnr [Leader] entering Leader state
INFO[2019-08-14 13:34:47] Server became metadata leader, performing leader promotion actions
INFO[2019-08-14 13:34:52] raft: Updating configuration with AddStaging (fp8btGxtuxbqn5LZl64AEf, fp8btGxtuxbqn5LZl64AEf) to [{Suffrage:Voter ID:RDEU1MVK78fAFhqDoGrvnr Address:RDEU1MVK78fAFhqDoGrvnr} {Suffrage:Voter ID:fp8btGxtuxbqn5LZl64AEf Address:fp8btGxtuxbqn5LZl64AEf}]
INFO[2019-08-14 13:34:52] raft: Added peer fp8btGxtuxbqn5LZl64AEf, starting replication
WARN[2019-08-14 13:34:52] raft: AppendEntries to {Voter fp8btGxtuxbqn5LZl64AEf fp8btGxtuxbqn5LZl64AEf} rejected, sending older logs (next: 1)
INFO[2019-08-14 13:34:52] raft: pipelining replication to peer {Voter fp8btGxtuxbqn5LZl64AEf fp8btGxtuxbqn5LZl64AEf}
INFO[2019-08-14 13:34:54] raft: Updating configuration with AddStaging (GNw4jnTEFA2OzvbYV3Pdyq, GNw4jnTEFA2OzvbYV3Pdyq) to [{Suffrage:Voter ID:RDEU1MVK78fAFhqDoGrvnr Address:RDEU1MVK78fAFhqDoGrvnr} {Suffrage:Voter ID:fp8btGxtuxbqn5LZl64AEf Address:fp8btGxtuxbqn5LZl64AEf} {Suffrage:Voter ID:GNw4jnTEFA2OzvbYV3Pdyq Address:GNw4jnTEFA2OzvbYV3Pdyq}]
INFO[2019-08-14 13:34:54] raft: Added peer GNw4jnTEFA2OzvbYV3Pdyq, starting replication
WARN[2019-08-14 13:34:54] raft: AppendEntries to {Voter GNw4jnTEFA2OzvbYV3Pdyq GNw4jnTEFA2OzvbYV3Pdyq} rejected, sending older logs (next: 1)
INFO[2019-08-14 13:34:54] raft: pipelining replication to peer {Voter GNw4jnTEFA2OzvbYV3Pdyq GNw4jnTEFA2OzvbYV3Pdyq}
Third peer:
$ docker run -it -p "9294:9292" --mount type=bind,source=liftbridge.conf,target=/liftbridge.conf liftbridge:latest --config /liftbridge.conf
INFO[2019-08-14 13:34:54] Server ID: GNw4jnTEFA2OzvbYV3Pdyq
INFO[2019-08-14 13:34:54] Namespace: liftbridge-default
INFO[2019-08-14 13:34:54] Retention Policy: [Age: 1 week, Compact: false]
INFO[2019-08-14 13:34:54] Starting server on 0.0.0.0:9292...
INFO[2019-08-14 13:34:54] raft: Initial configuration (index=0): []
DEBU[2019-08-14 13:34:54] Attempting to join metadata Raft group...
INFO[2019-08-14 13:34:54] raft: Node at GNw4jnTEFA2OzvbYV3Pdyq [Follower] entering Follower state (Leader: "")
DEBU[2019-08-14 13:34:54] raft-net: GNw4jnTEFA2OzvbYV3Pdyq accepted connection from: RDEU1MVK78fAFhqDoGrvnr
WARN[2019-08-14 13:34:54] raft: Failed to get previous log: 5 log not found (last: 0)
DEBU[2019-08-14 13:34:54] raft-net: GNw4jnTEFA2OzvbYV3Pdyq accepted connection from: RDEU1MVK78fAFhqDoGrvnr
go-liftbridge's version from go.mod:
# go.mod
github.com/liftbridge-io/go-liftbridge v0.0.0-20190704003903-285fd55a55b5
I only changed the addrs
variable from the example code, which now looks as follows:
addrs := []string{"dev.lan:9292", "dev.lan:9293", "dev.lan:9294"}
When I run the example I got the error above, and the following messages got logged by Liftbridge:
# Peer1
DEBU[2019-08-14 13:45:26] api: FetchMetadata [] [7/1989]
DEBU[2019-08-14 13:45:26] api: CreateStream [subject=foo, name=foo-stream, replicationFactor=1]
DEBU[2019-08-14 13:45:26] fsm: Created stream [subject=foo, name=foo-stream]
DEBU[2019-08-14 13:45:26] api: Publish [subject=foo]
DEBU[2019-08-14 13:45:26] api: FetchMetadata []
DEBU[2019-08-14 13:45:26] api: Subscribe [subject=foo, name=foo-stream, start=EARLIEST, offset=0, timestamp=-6795364578871345152]
ERRO[2019-08-14 13:45:26] api: Failed to subscribe to stream [subject=foo, name=foo-stream]: server not stream leader
DEBU[2019-08-14 13:45:26] api: FetchMetadata []
DEBU[2019-08-14 13:45:26] api: Subscribe [subject=foo, name=foo-stream, start=EARLIEST, offset=0, timestamp=-6795364578871345152]
ERRO[2019-08-14 13:45:26] api: Failed to subscribe to stream [subject=foo, name=foo-stream]: server not stream leader
DEBU[2019-08-14 13:45:26] api: FetchMetadata []
DEBU[2019-08-14 13:45:26] api: Subscribe [subject=foo, name=foo-stream, start=EARLIEST, offset=0, timestamp=-6795364578871345152]
ERRO[2019-08-14 13:45:26] api: Failed to subscribe to stream [subject=foo, name=foo-stream]: server not stream leader
DEBU[2019-08-14 13:45:26] api: FetchMetadata []
DEBU[2019-08-14 13:45:26] api: Subscribe [subject=foo, name=foo-stream, start=EARLIEST, offset=0, timestamp=-6795364578871345152]
ERRO[2019-08-14 13:45:26] api: Failed to subscribe to stream [subject=foo, name=foo-stream]: server not stream leader
DEBU[2019-08-14 13:45:26] api: FetchMetadata []
# Peer 2:
DEBU[2019-08-14 13:45:26] Server becoming leader for stream [subject=foo, name=foo-stream], epoch: 6
DEBU[2019-08-14 13:45:26] Updated stream leader epoch. New: {epoch:6, offset:-1}, Previous: {epoch:0, offset:-1} for stream [subject=foo, name=foo-stream]. Cache now contains 1 entry.
DEBU[2019-08-14 13:45:26] fsm: Created stream [subject=foo, name=foo-stream]
# Peer 3
DEBU[2019-08-14 13:45:26] fsm: Created stream [subject=foo, name=foo-stream]