search

liftbridge-io / liftbridge

Lightweight, fault-tolerant message streams.
https://liftbridge.io
Apache License 2.0
2.57k stars 107 forks source link

Server not stream leader #91

Closed laszbalo closed 5 years ago

laszbalo commented 5 years ago

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, 261249172984c54af4079588866a370469150764 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]
laszbalo commented 5 years ago

UPDATE:

Just tried running the Liftbridge cluster on different ports than 9292, 9293, 9294, and got a different error when calling client.Subscribe():

panic: rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = "transport: Error while dialing dial tcp 0.0.0.0:9292: connect: connection refused"

The stream got created and replicated successfully just as before.

Previously I wrote, that the client tries to subscribe to the first address on the list. But it might have tried to connect to 0.0.0.0:9292, which in my case, was the same as dev.lan:9292, which address happened to be the first one on the list.

UPDATE: It seems that the IP address which client.Subscribe() is trying to use comes from the value of the listen property of the liftbridge.conf file. At least, when I changed it from 0.0.0.0 to localhost, client.Subscribe() tried to connect to the IP of my machine. Also, when I skipped it entirely, just to rely on the default value, client.Subscribe() tried to connect :9292.

tylertreat commented 5 years ago

This sounds like unexpected behavior. What Subscribe should do is check the client's local metadata cache to see if it knows the broker address for the stream leader. If it doesn't have it, it will fetch the metadata. If it does have it, and it sends the request but the broker is no longer the leader, it should refresh the metadata and retry.

Basically, the address Subscribe uses comes from the metadata which is fetched from the cluster and refreshed/retried on failures.

I will see if I can reproduce your issue.

laszbalo commented 5 years ago

Thanks for your detailed explanation. Based on what you just described, it seems that Subscribe is trying to connect to my remote servers using the syntax for announcing local network addresses.

By default Docker containers have IP addresses from the 172.17.0.x/16 range. But my client code is running on the 192.168.0.x IP range.

tylertreat commented 5 years ago

I think the issue is that the metadata returned by the cluster uses the host and port as specified in the server config file for each broker:

https://github.com/liftbridge-io/liftbridge/blob/cd28b8e6e731c1706af7f0e8551fcf4101b58381/server/metadata.go#L181-L182 https://github.com/liftbridge-io/liftbridge/blob/cd28b8e6e731c1706af7f0e8551fcf4101b58381/server/server.go#L613-L614

tylertreat commented 5 years ago

I think this issue should be addressed with #98 which separates the listen address (what the server binds to) and host/port (what the server advertises to clients through the metadata API). You just need to make sure host/port is set to the actual external-facing address you want to connect to. Closing for now, but feel free to re-open if the issue isn't resolved.