Habitat: Nodes don't agree on leader after election

[bodymindarts]

Using hab-sup 0.22.1 I am running a test to ensure expected behaviour when nodes leave and come back.

The test is:

• bring up 3 nodes
• write a value
• destroy 2 nodes
• bring up 2 more nodes
• ensure that a new leader is elected (FAIL)

In the output below pg1 and pg2 were recreated while pg3 wasn't destroyed and should be elected leader again once they return. Unfortunately the nodes don't agree on a leader. pg1 and pg2 think its pg3 (which it should be) while pg3 thinks its one of the old leader that got destroyed.

This behaviour can be reproduced using delmo via:

git clone https://github.com/starkandwayne/habitat-plans
delmo -f habitat-plans/postgresql/tests/delmo.yml replication

It doesn't always fail at the same step, but it does consistently fail even though it was working with v0.21.0.

output
pg1

hab-sup(MN):
hab-sup(MN): WARNING: Setting '--config-from /conf' should only be used in development, not production!
hab-sup(MN):
hab-sup(MR): Supervisor Member-ID cc308708a56345ac88f6a08ecb7305b2
hab-sup(MR): Starting starkandwayne/postgresql
hab-sup(MR): Starting gossip-listener on 0.0.0.0:9638
hab-sup(MR): Starting http-gateway on 0.0.0.0:9631
ERROR:habitat_butterfly::server::outbound: Discarding ack from [email protected]:9638; expected 34583255dc364c29922233fb8cfb20ab
postgresql.cluster(SR): Hooks recompiled
cluster(CF): Updated postgresql.conf fc63a2b6e14aea7c0d6143b2736b7f859f7821ce7ef36573e98dd6c267490138
cluster(CF): Updated pg_hba.conf 0bf942c14bab24fc19481fbf74740fcea7aff4be99e7571feb5227d45465a95a
cluster(CF): Updated pwfile 30087c89f3dfc2b2179a2b567a67f094cf1cd8b1c6e3cc1473aef95fe65de533
cluster(CF): Updated .pgpass 77e2dc1737f58c6a9e2b967fbe9f0f0a6ba553a1e76e066fdcb61876f0d2e278
cluster(CF): Updated recovery.conf afa3970a2157f8d8897857ca0b86bc19ce646fec48b4b221dab121d5f5b2ae83
cluster(CF): Updated wal-e.toml f66872b154a21b81a8967cf8ffee822beb7e5fe6de7abac90c3002b0be8f8964
cluster(CF): Updated functions.sh e9b1e36b17253bc184ae3a71b33088b04f689b1638cfa9e133ee16f382f1040d
postgresql.cluster(SR): Configuration recompiled
postgresql.cluster(SR): Waiting to execute hooks; election in progress, and we have no quorum.
postgresql.cluster(SR): Hooks recompiled
cluster(CF): Updated recovery.conf 8d5da088760e34b169c4f18efb442004315fc4c01c914900b74783a287446877
cluster(CF): Updated functions.sh cb83a7f273421a8796339ba58ae03672a4e26392e17df38e05aef60c27801c34
postgresql.cluster(SR): Configuration recompiled
postgresql.cluster(SR): Executing hooks; 34583255dc364c29922233fb8cfb20ab is the leader
postgresql.cluster(SR): Initializing
(...)

pg2

hab-sup(MN):
hab-sup(MN): WARNING: Setting '--config-from /conf' should only be used in development, not production!
hab-sup(MN):
hab-sup(MR): Supervisor Member-ID 7db419e1394b4a16a32ef24beb9393c6
hab-sup(MR): Starting starkandwayne/postgresql
hab-sup(MR): Starting gossip-listener on 0.0.0.0:9638
hab-sup(MR): Starting http-gateway on 0.0.0.0:9631
postgresql.cluster(SR): Hooks recompiled
cluster(CF): Updated functions.sh e9b1e36b17253bc184ae3a71b33088b04f689b1638cfa9e133ee16f382f1040d
cluster(CF): Updated .pgpass 77e2dc1737f58c6a9e2b967fbe9f0f0a6ba553a1e76e066fdcb61876f0d2e278
cluster(CF): Updated recovery.conf afa3970a2157f8d8897857ca0b86bc19ce646fec48b4b221dab121d5f5b2ae83
cluster(CF): Updated wal-e.toml f66872b154a21b81a8967cf8ffee822beb7e5fe6de7abac90c3002b0be8f8964
cluster(CF): Updated pg_hba.conf 0bf942c14bab24fc19481fbf74740fcea7aff4be99e7571feb5227d45465a95a
cluster(CF): Updated postgresql.conf fc63a2b6e14aea7c0d6143b2736b7f859f7821ce7ef36573e98dd6c267490138
cluster(CF): Updated pwfile 30087c89f3dfc2b2179a2b567a67f094cf1cd8b1c6e3cc1473aef95fe65de533
postgresql.cluster(SR): Configuration recompiled
postgresql.cluster(SR): Waiting to execute hooks; election in progress, and we have no quorum.
postgresql.cluster(SR): Hooks recompiled
postgresql.cluster(SR): Waiting to execute hooks; election in progress.
postgresql.cluster(SR): Hooks recompiled
cluster(CF): Updated functions.sh cb83a7f273421a8796339ba58ae03672a4e26392e17df38e05aef60c27801c34
cluster(CF): Updated recovery.conf 8d5da088760e34b169c4f18efb442004315fc4c01c914900b74783a287446877
postgresql.cluster(SR): Configuration recompiled
postgresql.cluster(SR): Executing hooks; 34583255dc364c29922233fb8cfb20ab is the leader
postgresql.cluster(SR): Initializing
(...)

pg3

hab-sup(MN):
hab-sup(MN): WARNING: Setting '--config-from /conf' should only be used in development, not production!
hab-sup(MN):
hab-sup(MR): Supervisor Member-ID 34583255dc364c29922233fb8cfb20ab
hab-sup(MR): Starting starkandwayne/postgresql
hab-sup(MR): Starting gossip-listener on 0.0.0.0:9638
hab-sup(MR): Starting http-gateway on 0.0.0.0:9631
postgresql.cluster(SR): Hooks recompiled
cluster(CF): Updated postgresql.conf fc63a2b6e14aea7c0d6143b2736b7f859f7821ce7ef36573e98dd6c267490138
cluster(CF): Updated wal-e.toml f66872b154a21b81a8967cf8ffee822beb7e5fe6de7abac90c3002b0be8f8964
cluster(CF): Updated pg_hba.conf 0bf942c14bab24fc19481fbf74740fcea7aff4be99e7571feb5227d45465a95a
cluster(CF): Updated .pgpass 77e2dc1737f58c6a9e2b967fbe9f0f0a6ba553a1e76e066fdcb61876f0d2e278
cluster(CF): Updated pwfile 30087c89f3dfc2b2179a2b567a67f094cf1cd8b1c6e3cc1473aef95fe65de533
cluster(CF): Updated functions.sh e9b1e36b17253bc184ae3a71b33088b04f689b1638cfa9e133ee16f382f1040d
cluster(CF): Updated recovery.conf afa3970a2157f8d8897857ca0b86bc19ce646fec48b4b221dab121d5f5b2ae83
postgresql.cluster(SR): Configuration recompiled
postgresql.cluster(SR): Waiting to execute hooks; election in progress, and we have no quorum.
postgresql.cluster(SR): Hooks recompiled
postgresql.cluster(SR): Waiting to execute hooks; election in progress.
postgresql.cluster(SR): Hooks recompiled
cluster(CF): Updated functions.sh 8df8e6b96e83382ada5c897cfe4b7eb7b280154d18ea89d63d55da8539b4a5b1
cluster(CF): Updated recovery.conf cfc9f7436c63747e91e67a804a454a5c477f3a1bfbf5d1e04f00a321cc4e45df
postgresql.cluster(SR): Configuration recompiled
postgresql.cluster(SR): Executing hooks; 60da909a9ade40688b600d8538010124 is the leader
postgresql.cluster(SR): Initializing
postgresql.cluster hook[init]:(HK): Executing init hook
postgresql.cluster hook[init]:(HK): Exporting PGPASSFILE and setting permissions to 0600
postgresql.cluster hook[init]:(HK): Making sure hab user owns var, config and data paths
postgresql.cluster hook[init]:(HK): Making sure replication role exists on Master
postgresql.cluster(SV): Starting process as user=root, group=root
postgresql.cluster(O): Executing run hook
postgresql.cluster(O): Exporting PGPASSFILE and setting permissions to 0600
postgresql.cluster(O): Bootstrapping replica via pg_basebackup from leader
postgresql.cluster(O): Making sure hab user owns var, config and data paths
postgresql.cluster(O): Starting PostgreSQL
postgresql.cluster(O): 2017-05-11 08:53:08.102 GMT: LOG:  redirecting log output to logging collector process
postgresql.cluster(O): 2017-05-11 08:53:08.102 GMT: HINT:  Future log output will appear in directory "/hab/svc/postgresql/var/pg_log".
postgresql.cluster(SR): Hooks recompiled
Could not send rumor to Member { proto: id: "5e14b16a0f884c47aeb3d94e847bb3d5" incarnation: 0 address: "172.31.0.6" swim_port: 9638 gossip_port: 9638 persistent: false }; ZMQ said:
Resource temporarily unavailable
Could not send rumor to Member { proto: id: "60da909a9ade40688b600d8538010124" incarnation: 0 address: "172.31.0.3" swim_port: 9638 gossip_port: 9638 persistent: false }; ZMQ said:
Resource temporarily unavailable
Could not send rumor to Member { proto: id: "5e14b16a0f884c47aeb3d94e847bb3d5" incarnation: 0 address: "172.31.0.6" swim_port: 9638 gossip_port: 9638 persistent: false }; ZMQ said:
Resource temporarily unavailable
Could not send rumor to Member { proto: id: "60da909a9ade40688b600d8538010124" incarnation: 0 address: "172.31.0.3" swim_port: 9638 gossip_port: 9638 persistent: false }; ZMQ said:
Resource temporarily unavailable
postgresql.cluster hook[suitability]:(HK): 100663448
postgresql.cluster(HK): Reporting suitability of: 100663448
postgresql.cluster(SR): Hooks recompiled
postgresql.cluster(SR): Waiting to execute hooks; election in progress, and we have no quorum.
postgresql.cluster(SR): Hooks recompiled
postgresql.cluster(SR): Hooks recompiled
postgresql.cluster(SR): Executing hooks; 60da909a9ade40688b600d8538010124 is the leader
hab-sup(MR): Shutting down postgresql.cluster [starkandwayne/postgresql/9.6.1/20170510143046]
(...)

[adamhjk]

I have a fix mostly done for this.

[bixu]

Is there a place to track progress on this? Thinking ahead to sequencing how we can bring this work into our stack at $job.

[christophermaier]

@bodymindarts Does this still fail for you with the latest Habitat supervisor? I haven't been able to replicate it.

[adamhjk]

Yeah - I fixed this with the departure work. We can close it.