search

hashicorp / consul

Consul is a distributed, highly available, and data center aware solution to connect and configure applications across dynamic, distributed infrastructure.
https://www.consul.io
Other
28.27k stars 4.42k forks source link

[Unstable Tests] Unstable tests on Master #8686

Open pierresouchay opened 4 years ago

pierresouchay commented 4 years ago

Here are 2 unstable tests I found while doing PR https://github.com/hashicorp/consul/pull/8685 from master 86e7274a70db1803f3c4bb68d8dccbc01dbf3b5b

  1. TestACLTokenReap_Primary
Failed
=== RUN   TestACLTokenReap_Primary/local/one_should_be_reaped
=== CONT  TestACLTokenReap_Primary/local/one_should_be_reaped
    acl_token_exp_test.go:191: 
            Error Trace:    acl_token_exp_test.go:191
            Error:          Not equal: 
                            expected: 1
                            actual  : 0
            Test:           TestACLTokenReap_Primary/local/one_should_be_reaped
        --- FAIL: TestACLTokenReap_Primary/local/one_should_be_reaped (0.00s)

and

Failed
=== RUN   TestACLTokenReap_Primary/local/two_should_be_reaped
=== CONT  TestACLTokenReap_Primary/local/two_should_be_reaped
    acl_token_exp_test.go:208: 
            Error Trace:    acl_token_exp_test.go:208
            Error:          Not equal: 
                            expected: 1
                            actual  : 0
            Test:           TestACLTokenReap_Primary/local/two_should_be_reaped
        --- FAIL: TestACLTokenReap_Primary/local/two_should_be_reaped (0.00s)
  1. TestLeader_SecondaryCA_IntermediateRenew
=== RUN   TestLeader_SecondaryCA_IntermediateRenew
    leader_connect_test.go:302: 
            Error Trace:    leader_connect_test.go:302
            Error:          Received unexpected error:
                            x509: certificate signed by unknown authority (possibly because of "x509: ECDSA verification failure" while trying to verify candidate authority certificate "sec-13d5osd.consul.ca.813bb1b6.consul")
            Test:           TestLeader_SecondaryCA_IntermediateRenew
2020-09-15T10:23:50.570Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.raft: initial configuration: index=1 servers="[{Suffrage:Voter ID:015d58ec-f3ab-7862-826f-af14c94e92ee Address:127.0.0.1:26534}]"
2020-09-15T10:23:50.570Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.raft: entering follower state: follower="Node at 127.0.0.1:26534 [Follower]" leader=
2020-09-15T10:23:50.570Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.serf.wan: serf: EventMemberJoin: TestLeader_SecondaryCA_IntermediateRenew-node-12.dc2 127.0.0.1
2020-09-15T10:23:50.571Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.serf.lan: serf: EventMemberJoin: TestLeader_SecondaryCA_IntermediateRenew-node-12 127.0.0.1
2020-09-15T10:23:50.571Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.router: Initializing LAN area manager
2020-09-15T10:23:50.571Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server: Adding LAN server: server="TestLeader_SecondaryCA_IntermediateRenew-node-12 (Addr: tcp/127.0.0.1:26534) (DC: dc2)"
2020-09-15T10:23:50.571Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server: Handled event for server in area: event=member-join server=TestLeader_SecondaryCA_IntermediateRenew-node-12.dc2 area=wan
2020-09-15T10:23:50.571Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.server.memberlist.wan: memberlist: Initiating push/pull sync with: TestLeader_SecondaryCA_IntermediateRenew-node-11.dc1 127.0.0.1:26533
2020-09-15T10:23:50.572Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.serf.wan: serf: EventMemberJoin: TestLeader_SecondaryCA_IntermediateRenew-node-11.dc1 127.0.0.1
2020-09-15T10:23:50.572Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server: Handled event for server in area: event=member-join server=TestLeader_SecondaryCA_IntermediateRenew-node-11.dc1 area=wan
2020-09-15T10:23:50.671Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.server.serf.wan: serf: messageJoinType: TestLeader_SecondaryCA_IntermediateRenew-node-12.dc2
2020-09-15T10:23:50.690Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.server.serf.wan: serf: messageJoinType: TestLeader_SecondaryCA_IntermediateRenew-node-12.dc2
2020-09-15T10:23:50.790Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.server.serf.wan: serf: messageJoinType: TestLeader_SecondaryCA_IntermediateRenew-node-12.dc2
2020-09-15T10:23:50.790Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.server.serf.wan: serf: messageJoinType: TestLeader_SecondaryCA_IntermediateRenew-node-12.dc2
2020-09-15T10:23:50.862Z [WARN]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.raft: heartbeat timeout reached, starting election: last-leader=
2020-09-15T10:23:50.862Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.raft: entering candidate state: node="Node at 127.0.0.1:26534 [Candidate]" term=2
2020-09-15T10:23:50.863Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.server.raft: votes: needed=1
2020-09-15T10:23:50.863Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.server.raft: vote granted: from=015d58ec-f3ab-7862-826f-af14c94e92ee term=2 tally=1
2020-09-15T10:23:50.863Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.raft: election won: tally=1
2020-09-15T10:23:50.863Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.raft: entering leader state: leader="Node at 127.0.0.1:26534 [Leader]"
2020-09-15T10:23:50.863Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server: cluster leadership acquired
2020-09-15T10:23:50.863Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server: New leader elected: payload=TestLeader_SecondaryCA_IntermediateRenew-node-12
2020-09-15T10:23:50.863Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.server: Cannot upgrade to new ACLs, servers in acl datacenter are not yet upgraded: ACLDatacenter=dc1 mode=0 found=true
2020-09-15T10:23:50.865Z [DEBUG] connect.ca.consul: consul CA provider configured: id=ad:4a:c6:ab:ef:63:c9:60:1a:51:7f:19:62:e3:e9:d9:0e:76:55:10:6e:74:24:69:28:a1:6c:b8:b9:8f:fd:89 is_primary=false
2020-09-15T10:23:50.868Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.connect: received new intermediate certificate from primary datacenter
2020-09-15T10:23:50.868Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.connect: updated root certificates from primary datacenter
2020-09-15T10:23:50.868Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.connect: initialized secondary datacenter CA with provider: provider=consul
2020-09-15T10:23:50.868Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.leader: started routine: routine="config entry replication"
2020-09-15T10:23:50.868Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.leader: started routine: routine="federation state replication"
2020-09-15T10:23:50.868Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.leader: started routine: routine="federation state anti-entropy"
2020-09-15T10:23:50.869Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.leader: started routine: routine="secondary CA roots watch"
2020-09-15T10:23:50.869Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.leader: started routine: routine="intention replication"
2020-09-15T10:23:50.869Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.leader: started routine: routine="secondary cert renew watch"
2020-09-15T10:23:50.869Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.leader: started routine: routine="CA root pruning"
2020-09-15T10:23:50.869Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.server.connect: starting Connect CA root replication from primary datacenter: primary=dc1
2020-09-15T10:23:50.869Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.server.connect: starting Connect intention replication from primary datacenter: primary=dc1
2020-09-15T10:23:50.869Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.server: Skipping self join check for node since the cluster is too small: node=TestLeader_SecondaryCA_IntermediateRenew-node-12
2020-09-15T10:23:50.869Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server: member joined, marking health alive: member=TestLeader_SecondaryCA_IntermediateRenew-node-12
2020-09-15T10:23:50.869Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.server.replication.config_entry: finished fetching config entries: amount=0
2020-09-15T10:23:50.869Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.server.replication.config_entry: Config Entry replication: local=0 remote=0
2020-09-15T10:23:50.869Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.server.replication.config_entry: Config Entry replication: deletions=0 updates=0
2020-09-15T10:23:50.869Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.server.replication.config_entry: replication completed through remote index: index=1
2020-09-15T10:23:50.869Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.server: finished fetching remote objects: amount=1
2020-09-15T10:23:50.869Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.server: diffing replication state: local_amount=0 remote_amount=1
2020-09-15T10:23:50.869Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.server: diffed replication state: deletions=0 updates=1
2020-09-15T10:23:50.869Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.server: performing updates: updates=1
2020-09-15T10:23:50.869Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server: federation state anti-entropy synced
2020-09-15T10:23:50.870Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.server: finished updates
2020-09-15T10:23:50.870Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.replication.federation_state: replication completed through remote index: index=10
2020-09-15T10:23:50.870Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.server: finished fetching remote objects: amount=2
2020-09-15T10:23:50.870Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.server: diffing replication state: local_amount=1 remote_amount=2
2020-09-15T10:23:50.870Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.server: diffed replication state: deletions=0 updates=1
2020-09-15T10:23:50.870Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.server: performing updates: updates=1
2020-09-15T10:23:50.871Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server: federation state anti-entropy synced
2020-09-15T10:23:50.871Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.server: finished updates
2020-09-15T10:23:50.871Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.replication.federation_state: replication completed through remote index: index=14
2020-09-15T10:23:50.872Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.server: finished fetching remote objects: amount=2
2020-09-15T10:23:50.872Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.server: diffing replication state: local_amount=2 remote_amount=2
2020-09-15T10:23:50.872Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.server: diffed replication state: deletions=0 updates=1
2020-09-15T10:23:50.872Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.server: performing updates: updates=1
2020-09-15T10:23:50.872Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.server: finished updates
2020-09-15T10:23:50.872Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.replication.federation_state: replication completed through remote index: index=15
2020-09-15T10:23:50.874Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.connect: received new intermediate certificate from primary datacenter
2020-09-15T10:23:50.875Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.connect: updated root certificates from primary datacenter
2020-09-15T10:23:50.879Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.connect: received new intermediate certificate from primary datacenter
2020-09-15T10:23:50.880Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.connect: updated root certificates from primary datacenter
2020-09-15T10:23:50.884Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.connect: received new intermediate certificate from primary datacenter
2020-09-15T10:23:50.885Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.connect: updated root certificates from primary datacenter
2020-09-15T10:23:50.889Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.connect: received new intermediate certificate from primary datacenter
2020-09-15T10:23:50.889Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.connect: updated root certificates from primary datacenter
2020-09-15T10:23:50.893Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.connect: received new intermediate certificate from primary datacenter
2020-09-15T10:23:50.894Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.connect: updated root certificates from primary datacenter
2020-09-15T10:23:50.898Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.connect: received new intermediate certificate from primary datacenter
2020-09-15T10:23:50.899Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.connect: updated root certificates from primary datacenter
2020-09-15T10:23:50.903Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.connect: received new intermediate certificate from primary datacenter
2020-09-15T10:23:50.903Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.connect: updated root certificates from primary datacenter
2020-09-15T10:23:50.908Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.connect: received new intermediate certificate from primary datacenter
2020-09-15T10:23:50.908Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.connect: updated root certificates from primary datacenter
2020-09-15T10:23:50.912Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.connect: received new intermediate certificate from primary datacenter
2020-09-15T10:23:50.914Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.connect: updated root certificates from primary datacenter
2020-09-15T10:23:50.917Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server: shutting down server
2020-09-15T10:23:50.917Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.leader: stopping routine: routine="config entry replication"
2020-09-15T10:23:50.917Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.leader: stopping routine: routine="federation state replication"
2020-09-15T10:23:50.917Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.leader: stopping routine: routine="federation state anti-entropy"
2020-09-15T10:23:50.917Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.leader: stopping routine: routine="secondary CA roots watch"
2020-09-15T10:23:50.917Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.leader: stopping routine: routine="intention replication"
2020-09-15T10:23:50.917Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.leader: stopping routine: routine="secondary cert renew watch"
2020-09-15T10:23:50.917Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.leader: stopping routine: routine="CA root pruning"
2020-09-15T10:23:50.917Z [WARN]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.serf.lan: serf: Shutdown without a Leave
2020-09-15T10:23:50.917Z [ERROR] TestLeader_SecondaryCA_IntermediateRenew-node-12.server: error performing anti-entropy sync of federation state: error="context canceled"
2020-09-15T10:23:50.917Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.leader: stopped routine: routine="CA root pruning"
2020-09-15T10:23:50.917Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.leader: stopped routine: routine="federation state anti-entropy"
2020-09-15T10:23:50.917Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.server.usage_metrics: usage metrics reporter shutting down
2020-09-15T10:23:50.917Z [WARN]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.serf.wan: serf: Shutdown without a Leave
2020-09-15T10:23:50.917Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.router.manager: shutting down
2020-09-15T10:23:50.917Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.router.manager: shutting down
2020-09-15T10:23:50.917Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.router.manager: shutting down
2020-09-15T10:23:50.918Z [ERROR] TestLeader_SecondaryCA_IntermediateRenew-node-12.server.connect: error renewing intermediate certs: routine="secondary cert renew watch" error="Failed to set the intermediate certificate with the CA provider: raft is already shutdown"
2020-09-15T10:23:50.918Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.leader: stopped routine: routine="secondary cert renew watch"
2020-09-15T10:23:50.918Z [ERROR] TestLeader_SecondaryCA_IntermediateRenew-node-12.server.rpc: RPC failed to server in DC: server=127.0.0.1:26531 datacenter=dc1 method=ConnectCA.Roots error="rpc error making call: EOF"
2020-09-15T10:23:50.918Z [ERROR] TestLeader_SecondaryCA_IntermediateRenew-node-12.server.rpc: RPC failed to server in DC: server=127.0.0.1:26531 datacenter=dc1 method=FederationState.List error="rpc error making call: EOF"
2020-09-15T10:23:50.918Z [ERROR] TestLeader_SecondaryCA_IntermediateRenew-node-12.server.rpc: RPC failed to server in DC: server=127.0.0.1:26531 datacenter=dc1 method=ConfigEntry.ListAll error="rpc error making call: EOF"
2020-09-15T10:23:50.918Z [WARN]  TestLeader_SecondaryCA_IntermediateRenew-node-12.replication.federation_state: replication error (will retry if still leader): error="failed to retrieve federation states: rpc error making call: EOF"
2020-09-15T10:23:50.918Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.replication.federation_state: stopped replication
2020-09-15T10:23:50.918Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.leader: stopped routine: routine="federation state replication"
2020-09-15T10:23:50.918Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-12.server.replication.config_entry: stopped replication
2020-09-15T10:23:50.918Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.leader: stopped routine: routine="config entry replication"
2020-09-15T10:23:50.918Z [ERROR] TestLeader_SecondaryCA_IntermediateRenew-node-12.server.rpc: RPC failed to server in DC: server=127.0.0.1:26531 datacenter=dc1 method=Intention.List error="rpc error making call: EOF"
2020-09-15T10:23:50.918Z [ERROR] TestLeader_SecondaryCA_IntermediateRenew-node-12.server.connect: error replicating intentions: routine="intention replication" error="rpc error making call: EOF"
2020-09-15T10:23:50.918Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.leader: stopped routine: routine="intention replication"
2020-09-15T10:23:50.918Z [ERROR] TestLeader_SecondaryCA_IntermediateRenew-node-12.server.connect: CA root replication failed, will retry: routine="secondary CA roots watch" error="Error retrieving the primary datacenter's roots: rpc error making call: EOF"
2020-09-15T10:23:50.918Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-12.leader: stopped routine: routine="secondary CA roots watch"
2020-09-15T10:23:50.289Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-11.server.raft: initial configuration: index=1 servers="[{Suffrage:Voter ID:ee6868b7-0045-50d8-16d7-c946b96d03d4 Address:127.0.0.1:26531}]"
2020-09-15T10:23:50.289Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-11.server.raft: entering follower state: follower="Node at 127.0.0.1:26531 [Follower]" leader=
2020-09-15T10:23:50.289Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-11.server.serf.wan: serf: EventMemberJoin: TestLeader_SecondaryCA_IntermediateRenew-node-11.dc1 127.0.0.1
2020-09-15T10:23:50.290Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-11.server.serf.lan: serf: EventMemberJoin: TestLeader_SecondaryCA_IntermediateRenew-node-11 127.0.0.1
2020-09-15T10:23:50.290Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-11.server.router: Initializing LAN area manager
2020-09-15T10:23:50.290Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-11.server: Adding LAN server: server="TestLeader_SecondaryCA_IntermediateRenew-node-11 (Addr: tcp/127.0.0.1:26531) (DC: dc1)"
2020-09-15T10:23:50.290Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-11.server: Handled event for server in area: event=member-join server=TestLeader_SecondaryCA_IntermediateRenew-node-11.dc1 area=wan
2020-09-15T10:23:50.496Z [WARN]  TestLeader_SecondaryCA_IntermediateRenew-node-11.server.raft: heartbeat timeout reached, starting election: last-leader=
2020-09-15T10:23:50.496Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-11.server.raft: entering candidate state: node="Node at 127.0.0.1:26531 [Candidate]" term=2
2020-09-15T10:23:50.496Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-11.server.raft: votes: needed=1
2020-09-15T10:23:50.496Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-11.server.raft: vote granted: from=ee6868b7-0045-50d8-16d7-c946b96d03d4 term=2 tally=1
2020-09-15T10:23:50.496Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-11.server.raft: election won: tally=1
2020-09-15T10:23:50.496Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-11.server.raft: entering leader state: leader="Node at 127.0.0.1:26531 [Leader]"
2020-09-15T10:23:50.496Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-11.server: cluster leadership acquired
2020-09-15T10:23:50.496Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-11.server: New leader elected: payload=TestLeader_SecondaryCA_IntermediateRenew-node-11
2020-09-15T10:23:50.497Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-11.server: Cannot upgrade to new ACLs: leaderMode=0 mode=0 found=true leader=127.0.0.1:26531
2020-09-15T10:23:50.498Z [DEBUG] connect.ca.consul: consul CA provider configured: id=07:80:c8:de:f6:41:86:29:8f:9c:b8:17:d6:48:c2:d5:c5:5c:7f:0c:03:f7:cf:97:5a:a7:c1:68:aa:23:ae:81 is_primary=true
2020-09-15T10:23:50.499Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-11.server.connect: initialized primary datacenter CA with provider: provider=consul
2020-09-15T10:23:50.499Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-11.leader: started routine: routine="federation state anti-entropy"
2020-09-15T10:23:50.499Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-11.leader: started routine: routine="federation state pruning"
2020-09-15T10:23:50.499Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-11.leader: started routine: routine="CA root pruning"
2020-09-15T10:23:50.499Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-11.server: Skipping self join check for node since the cluster is too small: node=TestLeader_SecondaryCA_IntermediateRenew-node-11
2020-09-15T10:23:50.499Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-11.server: member joined, marking health alive: member=TestLeader_SecondaryCA_IntermediateRenew-node-11
2020-09-15T10:23:50.500Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-11.server: federation state anti-entropy synced
2020-09-15T10:23:50.571Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-11.server.memberlist.wan: memberlist: Stream connection from=127.0.0.1:53734
2020-09-15T10:23:50.572Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-11.server.serf.wan: serf: EventMemberJoin: TestLeader_SecondaryCA_IntermediateRenew-node-12.dc2 127.0.0.1
2020-09-15T10:23:50.572Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-11.server: Handled event for server in area: event=member-join server=TestLeader_SecondaryCA_IntermediateRenew-node-12.dc2 area=wan
2020-09-15T10:23:50.590Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-11.server.serf.wan: serf: messageJoinType: TestLeader_SecondaryCA_IntermediateRenew-node-12.dc2
2020-09-15T10:23:50.671Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-11.server.serf.wan: serf: messageJoinType: TestLeader_SecondaryCA_IntermediateRenew-node-12.dc2
2020-09-15T10:23:50.671Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-11.server.serf.wan: serf: messageJoinType: TestLeader_SecondaryCA_IntermediateRenew-node-12.dc2
2020-09-15T10:23:50.771Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-11.server.serf.wan: serf: messageJoinType: TestLeader_SecondaryCA_IntermediateRenew-node-12.dc2
2020-09-15T10:23:50.797Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-11.server: Skipping self join check for node since the cluster is too small: node=TestLeader_SecondaryCA_IntermediateRenew-node-11
2020-09-15T10:23:50.919Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-11.server: shutting down server
2020-09-15T10:23:50.919Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-11.leader: stopping routine: routine="federation state anti-entropy"
2020-09-15T10:23:50.919Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-11.leader: stopping routine: routine="federation state pruning"
2020-09-15T10:23:50.919Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-11.leader: stopping routine: routine="CA root pruning"
2020-09-15T10:23:50.919Z [WARN]  TestLeader_SecondaryCA_IntermediateRenew-node-11.server.serf.lan: serf: Shutdown without a Leave
2020-09-15T10:23:50.919Z [ERROR] TestLeader_SecondaryCA_IntermediateRenew-node-11.server: error performing anti-entropy sync of federation state: error="context canceled"
2020-09-15T10:23:50.919Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-11.leader: stopped routine: routine="federation state pruning"
2020-09-15T10:23:50.919Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-11.leader: stopped routine: routine="federation state anti-entropy"
2020-09-15T10:23:50.919Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-11.server.usage_metrics: usage metrics reporter shutting down
2020-09-15T10:23:50.919Z [DEBUG] TestLeader_SecondaryCA_IntermediateRenew-node-11.leader: stopped routine: routine="CA root pruning"
2020-09-15T10:23:50.920Z [WARN]  TestLeader_SecondaryCA_IntermediateRenew-node-11.server.serf.wan: serf: Shutdown without a Leave
2020-09-15T10:23:50.920Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-11.server.router.manager: shutting down
2020-09-15T10:23:50.920Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-11.server.router.manager: shutting down
2020-09-15T10:23:50.920Z [INFO]  TestLeader_SecondaryCA_IntermediateRenew-node-11.server.router.manager: shutting down
--- FAIL: TestLeader_SecondaryCA_IntermediateRenew (0.64s)
jsosulska commented 4 years ago

Also mentioned here: #7520

pierresouchay commented 3 years ago

Other unstable tests from https://app.circleci.com/pipelines/github/hashicorp/consul/14851/workflows/f43c32d0-09bc-4500-9891-4e4196cfe0c4/jobs/286619 :

TestACLEndpoint_Login_with_TokenLocality - github.com/hashicorp/consul/agent/consul

Failed
=== CONT  TestACLEndpoint_Login_with_TokenLocality

TestAgent_Leave - github.com/hashicorp/consul/agent

=== RUN   TestAgent_Leave
=== PAUSE TestAgent_Leave
=== CONT  TestAgent_Leave
[WARN] freeport: 4 out of 4 pending ports are still in use; something probably didn't wait around for the port to be closed!
[WARN] freeport: 4 out of 4 pending ports are still in use; something probably didn't wait around for the port to be closed!
[WARN] freeport: 4 out of 4 pending ports are still in use; something probably didn't wait around for the port to be closed!
[WARN] freeport: 4 out of 4 pending ports are still in use; something probably didn't wait around for the port to be closed!
[WARN] freeport: 4 out of 4 pending ports are still in use; something probably didn't wait around for the port to be closed!
[WARN] freeport: 4 out of 4 pending ports are still in use; something probably didn't wait around for the port to be closed!
[WARN] freeport: 4 out of 4 pending ports are still in use; something probably didn't wait around for the port to be closed!
[WARN] freeport: 4 out of 4 pending ports are still in use; something probably didn't wait around for the port to be closed!
[WARN] freeport: 4 out of 4 pending ports are still in use; something probably didn't wait around for the port to be closed!
[WARN] freeport: 4 out of 4 pending ports are still in use; something probably didn't wait around for the port to be closed!
[WARN] freeport: 4 out of 4 pending ports are still in use; something probably didn't wait around for the port to be closed!
[WARN] freeport: 4 out of 4 pending ports are still in use; something probably didn't wait around for the port to be closed!
[WARN] freeport: 4 out of 4 pending ports are still in use; something probably didn't wait around for the port to be closed!
[WARN] freeport: 4 out of 4 pending ports are still in use; something probably didn't wait around for the port to be closed!
[WARN] freeport: 4 out of 4 pending ports are still in use; something probably didn't wait around for the port to be closed!
[WARN] freeport: 4 out of 4 pending ports are still in use; something probably didn't wait around for the port to be closed!
[WARN] freeport: 4 out of 4 pending ports are still in use; something probably didn't wait around for the port to be closed!
[WARN] freeport: 4 out of 4 pending ports are still in use; something probably didn't wait around for the port to be closed!
[WARN] freeport: 4 out of 4 pending ports are still in use; something probably didn't wait around for the port to be closed!
[WARN] freeport: 4 out of 4 pending ports are still in use; something probably didn't wait around for the port to be closed!
[WARN] freeport: 4 out of 4 pending ports are still in use; something probably didn't wait around for the port to be closed!
[WARN] freeport: 4 out of 4 pending ports are still in use; something probably didn't wait around for the port to be closed!
[WARN] freeport: 4 out of 4 pending ports are still in use; something probably didn't wait around for the port to be closed!
[WARN] freeport: 4 out of 4 pending ports are still in use; something probably didn't wait around for the port to be closed!
2020-11-20T16:18:02.511Z [WARN]  agent: bootstrap = true: do not enable unless necessary
2020-11-20T16:18:02.516Z [WARN]  agent.auto_config: bootstrap = true: do not enable unless necessary
18:02.518 [INFO]  TestAgent.server.raft: initial configuration: index=1 servers="[{Suffrage:Voter ID:7db5f7e8-106d-2d14-d633-62067f62c1d8 Address:127.0.0.1:20779}]"
18:02.518 [INFO]  TestAgent.server.raft: entering follower state: follower="Node at 127.0.0.1:20779 [Follower]" leader=
18:02.518 [INFO]  TestAgent.server.serf.wan: serf: EventMemberJoin: Node-7db5f7e8-106d-2d14-d633-62067f62c1d8.dc1 127.0.0.1
18:02.518 [INFO]  TestAgent.server.serf.lan: serf: EventMemberJoin: Node-7db5f7e8-106d-2d14-d633-62067f62c1d8 127.0.0.1
2020-11-20T16:18:02.518Z [INFO]  agent.router: Initializing LAN area manager
18:02.518 [INFO]  TestAgent.server: Adding LAN server: server="Node-7db5f7e8-106d-2d14-d633-62067f62c1d8 (Addr: tcp/127.0.0.1:20779) (DC: dc1)"
18:02.518 [INFO]  TestAgent.server: Handled event for server in area: event=member-join server=Node-7db5f7e8-106d-2d14-d633-62067f62c1d8.dc1 area=wan
18:02.519 [INFO]  TestAgent: Started DNS server: address=127.0.0.1:20788 network=udp
18:02.519 [INFO]  TestAgent: Started DNS server: address=127.0.0.1:20788 network=tcp
18:02.519 [INFO]  TestAgent: Starting server: address=127.0.0.1:20775 network=tcp protocol=http
18:02.519 [WARN]  TestAgent: DEPRECATED Backwards compatibility with pre-1.9 metrics enabled. These metrics will be removed in a future version of Consul. Set `telemetry { disable_compat_1.9 = true }` to disable them.
18:02.519 [INFO]  TestAgent: started state syncer
18:02.519 [INFO]  TestAgent: Started gRPC server: address=127.0.0.1:20780 network=tcp
18:02.557 [WARN]  TestAgent.server.raft: heartbeat timeout reached, starting election: last-leader=
18:02.557 [INFO]  TestAgent.server.raft: entering candidate state: node="Node at 127.0.0.1:20779 [Candidate]" term=2
18:02.557 [DEBUG] TestAgent.server.raft: votes: needed=1
18:02.557 [DEBUG] TestAgent.server.raft: vote granted: from=7db5f7e8-106d-2d14-d633-62067f62c1d8 term=2 tally=1
18:02.557 [INFO]  TestAgent.server.raft: election won: tally=1
18:02.557 [INFO]  TestAgent.server.raft: entering leader state: leader="Node at 127.0.0.1:20779 [Leader]"
18:02.557 [INFO]  TestAgent.server: cluster leadership acquired
18:02.557 [INFO]  TestAgent.server: New leader elected: payload=Node-7db5f7e8-106d-2d14-d633-62067f62c1d8
18:02.558 [DEBUG] TestAgent.server: Cannot upgrade to new ACLs: leaderMode=0 mode=0 found=true leader=127.0.0.1:20779
18:02.558 [DEBUG] TestAgent.server.autopilot: autopilot is now running
18:02.558 [DEBUG] TestAgent.server.autopilot: state update routine is now running
18:02.559 [DEBUG] connect.ca.consul: consul CA provider configured: id=07:80:c8:de:f6:41:86:29:8f:9c:b8:17:d6:48:c2:d5:c5:5c:7f:0c:03:f7:cf:97:5a:a7:c1:68:aa:23:ae:81 is_primary=true
18:02.560 [INFO]  TestAgent.server.connect: initialized primary datacenter CA with provider: provider=consul
18:02.560 [INFO]  TestAgent.leader: started routine: routine="federation state anti-entropy"
18:02.560 [INFO]  TestAgent.leader: started routine: routine="federation state pruning"
18:02.560 [INFO]  TestAgent.leader: started routine: routine="intermediate cert renew watch"
18:02.560 [INFO]  TestAgent.leader: started routine: routine="CA root pruning"
18:02.560 [DEBUG] TestAgent.server: successfully established leadership: duration=2.539427ms
18:02.560 [INFO]  TestAgent.server: member joined, marking health alive: member=Node-7db5f7e8-106d-2d14-d633-62067f62c1d8
18:02.614 [DEBUG] TestAgent.server.memberlist.lan: memberlist: Stream connection from=127.0.0.1:46172
18:02.614 [INFO]  TestAgent.server.serf.lan: serf: EventMemberJoin: Node-22202af9-4692-0733-7051-66c318195dbb 127.0.0.1
18:02.614 [INFO]  TestAgent.server: Adding LAN server: server="Node-22202af9-4692-0733-7051-66c318195dbb (Addr: tcp/127.0.0.1:20758) (DC: dc1)"
18:02.614 [INFO]  TestAgent.server: New leader elected: payload=Node-22202af9-4692-0733-7051-66c318195dbb
18:02.614 [INFO]  TestAgent: Requesting shutdown
18:02.614 [INFO]  TestAgent.server: shutting down server
18:02.614 [ERROR] TestAgent.server: Two nodes are in bootstrap mode. Only one node should be in bootstrap mode, not adding Raft peer.: node_to_add=Node-22202af9-4692-0733-7051-66c318195dbb other=Node-7db5f7e8-106d-2d14-d633-62067f62c1d8
18:02.614 [INFO]  TestAgent.server: member joined, marking health alive: member=Node-22202af9-4692-0733-7051-66c318195dbb
18:02.614 [ERROR] TestAgent.server: error performing anti-entropy sync of federation state: error="shutdown waiting for leader"
18:02.614 [DEBUG] TestAgent.server.usage_metrics: usage metrics reporter shutting down
18:02.614 [ERROR] TestAgent.anti_entropy: failed to sync remote state: error="No cluster leader"
18:02.614 [DEBUG] TestAgent.server.memberlist.wan: memberlist: Initiating push/pull sync with: Node-22202af9-4692-0733-7051-66c318195dbb.dc1 127.0.0.1:20757
18:02.615 [DEBUG] TestAgent.server.memberlist.wan: memberlist: Stream connection from=127.0.0.1:55746
18:02.615 [INFO]  TestAgent.server.serf.wan: serf: EventMemberJoin: Node-22202af9-4692-0733-7051-66c318195dbb.dc1 127.0.0.1
18:02.614 [DEBUG] TestAgent.leader: stopping routine: routine="federation state anti-entropy"
18:02.615 [DEBUG] TestAgent.leader: stopping routine: routine="federation state pruning"
18:02.615 [DEBUG] TestAgent.leader: stopping routine: routine="intermediate cert renew watch"
18:02.615 [DEBUG] TestAgent.leader: stopping routine: routine="CA root pruning"
18:02.615 [WARN]  TestAgent.server.serf.lan: serf: Shutdown without a Leave
18:02.615 [DEBUG] TestAgent.leader: stopped routine: routine="federation state anti-entropy"
18:02.615 [DEBUG] TestAgent.leader: stopped routine: routine="federation state pruning"
18:02.615 [DEBUG] TestAgent.leader: stopped routine: routine="intermediate cert renew watch"
18:02.615 [DEBUG] TestAgent.leader: stopped routine: routine="CA root pruning"
18:02.615 [INFO]  TestAgent.server: Handled event for server in area: event=member-join server=Node-22202af9-4692-0733-7051-66c318195dbb.dc1 area=wan
18:02.615 [DEBUG] TestAgent.server.autopilot: state update routine is now stopped
18:02.615 [DEBUG] TestAgent.server.autopilot: autopilot is now stopped
18:02.615 [DEBUG] TestAgent.server: Successfully performed flood-join for server at address: server=Node-22202af9-4692-0733-7051-66c318195dbb.dc1 address=127.0.0.1:20757
18:02.615 [WARN]  TestAgent.server.serf.wan: serf: Shutdown without a Leave
2020-11-20T16:18:02.616Z [INFO]  agent.router.manager: shutting down
2020-11-20T16:18:02.616Z [INFO]  agent.router.manager: shutting down
18:02.616 [INFO]  TestAgent: consul server down
18:02.616 [INFO]  TestAgent: shutdown complete
18:02.616 [INFO]  TestAgent: Stopping server: protocol=DNS address=127.0.0.1:20788 network=tcp
18:02.616 [INFO]  TestAgent: Stopping server: protocol=DNS address=127.0.0.1:20788 network=udp
18:02.616 [INFO]  TestAgent: Stopping server: address=127.0.0.1:20775 network=tcp protocol=http
18:03.116 [INFO]  TestAgent: Waiting for endpoints to shut down
18:03.116 [INFO]  TestAgent: Endpoints down
2020-11-20T16:18:02.283Z [WARN]  agent: bootstrap = true: do not enable unless necessary
2020-11-20T16:18:02.288Z [WARN]  agent.auto_config: bootstrap = true: do not enable unless necessary
18:02.290 [INFO]  TestAgent.server.raft: initial configuration: index=1 servers="[{Suffrage:Voter ID:22202af9-4692-0733-7051-66c318195dbb Address:127.0.0.1:20758}]"
18:02.290 [INFO]  TestAgent.server.raft: entering follower state: follower="Node at 127.0.0.1:20758 [Follower]" leader=
18:02.290 [INFO]  TestAgent.server.serf.wan: serf: EventMemberJoin: Node-22202af9-4692-0733-7051-66c318195dbb.dc1 127.0.0.1
18:02.290 [INFO]  TestAgent.server.serf.lan: serf: EventMemberJoin: Node-22202af9-4692-0733-7051-66c318195dbb 127.0.0.1
2020-11-20T16:18:02.290Z [INFO]  agent.router: Initializing LAN area manager
18:02.290 [INFO]  TestAgent.server: Adding LAN server: server="Node-22202af9-4692-0733-7051-66c318195dbb (Addr: tcp/127.0.0.1:20758) (DC: dc1)"
18:02.290 [INFO]  TestAgent.server: Handled event for server in area: event=member-join server=Node-22202af9-4692-0733-7051-66c318195dbb.dc1 area=wan
18:02.291 [INFO]  TestAgent: Started DNS server: address=127.0.0.1:20753 network=udp
18:02.291 [INFO]  TestAgent: Started DNS server: address=127.0.0.1:20753 network=tcp
18:02.291 [INFO]  TestAgent: Starting server: address=127.0.0.1:20754 network=tcp protocol=http
18:02.291 [WARN]  TestAgent: DEPRECATED Backwards compatibility with pre-1.9 metrics enabled. These metrics will be removed in a future version of Consul. Set `telemetry { disable_compat_1.9 = true }` to disable them.
18:02.291 [INFO]  TestAgent: started state syncer
18:02.291 [INFO]  TestAgent: Started gRPC server: address=127.0.0.1:20759 network=tcp
18:02.354 [WARN]  TestAgent.server.raft: heartbeat timeout reached, starting election: last-leader=
18:02.354 [INFO]  TestAgent.server.raft: entering candidate state: node="Node at 127.0.0.1:20758 [Candidate]" term=2
18:02.354 [DEBUG] TestAgent.server.raft: votes: needed=1
18:02.354 [DEBUG] TestAgent.server.raft: vote granted: from=22202af9-4692-0733-7051-66c318195dbb term=2 tally=1
18:02.354 [INFO]  TestAgent.server.raft: election won: tally=1
18:02.354 [INFO]  TestAgent.server.raft: entering leader state: leader="Node at 127.0.0.1:20758 [Leader]"
18:02.354 [INFO]  TestAgent.server: cluster leadership acquired
18:02.354 [INFO]  TestAgent.server: New leader elected: payload=Node-22202af9-4692-0733-7051-66c318195dbb
18:02.354 [DEBUG] TestAgent.server: Cannot upgrade to new ACLs: leaderMode=0 mode=0 found=true leader=127.0.0.1:20758
18:02.355 [DEBUG] TestAgent.server.autopilot: autopilot is now running
18:02.355 [DEBUG] TestAgent.server.autopilot: state update routine is now running
18:02.356 [DEBUG] connect.ca.consul: consul CA provider configured: id=07:80:c8:de:f6:41:86:29:8f:9c:b8:17:d6:48:c2:d5:c5:5c:7f:0c:03:f7:cf:97:5a:a7:c1:68:aa:23:ae:81 is_primary=true
18:02.357 [INFO]  TestAgent.server.connect: initialized primary datacenter CA with provider: provider=consul
18:02.357 [INFO]  TestAgent.leader: started routine: routine="federation state anti-entropy"
18:02.357 [INFO]  TestAgent.leader: started routine: routine="federation state pruning"
18:02.357 [INFO]  TestAgent.leader: started routine: routine="intermediate cert renew watch"
18:02.357 [INFO]  TestAgent.leader: started routine: routine="CA root pruning"
18:02.357 [DEBUG] TestAgent.server: successfully established leadership: duration=2.623465ms
18:02.357 [INFO]  TestAgent.server: member joined, marking health alive: member=Node-22202af9-4692-0733-7051-66c318195dbb
18:02.495 [INFO]  TestAgent.server: federation state anti-entropy synced
18:02.614 [INFO]  TestAgent: (LAN) joining: lan_addresses=[127.0.0.1:20777]
18:02.614 [DEBUG] TestAgent.server.memberlist.lan: memberlist: Initiating push/pull sync with:  127.0.0.1:20777
18:02.614 [INFO]  TestAgent.server.serf.lan: serf: EventMemberJoin: Node-7db5f7e8-106d-2d14-d633-62067f62c1d8 127.0.0.1
18:02.614 [INFO]  TestAgent: (LAN) joined: number_of_nodes=1
18:02.614 [DEBUG] TestAgent: systemd notify failed: error="No socket"
18:02.614 [INFO]  TestAgent.server: Adding LAN server: server="Node-7db5f7e8-106d-2d14-d633-62067f62c1d8 (Addr: tcp/127.0.0.1:20779) (DC: dc1)"
18:02.614 [ERROR] TestAgent.server: Two nodes are in bootstrap mode. Only one node should be in bootstrap mode, not adding Raft peer.: node_to_add=Node-7db5f7e8-106d-2d14-d633-62067f62c1d8 other=Node-22202af9-4692-0733-7051-66c318195dbb
18:02.614 [INFO]  TestAgent.server: member joined, marking health alive: member=Node-7db5f7e8-106d-2d14-d633-62067f62c1d8
18:02.615 [DEBUG] TestAgent.server.memberlist.wan: memberlist: Initiating push/pull sync with: Node-7db5f7e8-106d-2d14-d633-62067f62c1d8.dc1 127.0.0.1:20778
18:02.615 [DEBUG] TestAgent.server.memberlist.wan: memberlist: Stream connection from=127.0.0.1:39274
18:02.615 [INFO]  TestAgent.server.serf.wan: serf: EventMemberJoin: Node-7db5f7e8-106d-2d14-d633-62067f62c1d8.dc1 127.0.0.1
18:02.615 [INFO]  TestAgent.server: Handled event for server in area: event=member-join server=Node-7db5f7e8-106d-2d14-d633-62067f62c1d8.dc1 area=wan
18:02.615 [DEBUG] TestAgent.server: Successfully performed flood-join for server at address: server=Node-7db5f7e8-106d-2d14-d633-62067f62c1d8.dc1 address=127.0.0.1:20778
18:02.678 [DEBUG] TestAgent: Skipping remote check since it is managed automatically: check=serfHealth
18:02.678 [INFO]  TestAgent: Synced node info
18:03.292 [DEBUG] TestAgent: Skipping remote check since it is managed automatically: check=serfHealth
18:03.292 [DEBUG] TestAgent: Node info in sync
18:03.292 [DEBUG] TestAgent: Node info in sync
18:03.791 [DEBUG] TestAgent.server.memberlist.lan: memberlist: Failed ping: Node-7db5f7e8-106d-2d14-d633-62067f62c1d8 (timeout reached)
18:04.291 [INFO]  TestAgent.server.memberlist.lan: memberlist: Suspect Node-7db5f7e8-106d-2d14-d633-62067f62c1d8 has failed, no acks received
18:04.356 [WARN]  TestAgent: error getting server health from server: server=Node-7db5f7e8-106d-2d14-d633-62067f62c1d8 error="rpc error getting client: failed to get conn: dial tcp 127.0.0.1:0->127.0.0.1:20779: connect: connection refused"
18:05.356 [WARN]  TestAgent: error getting server health from server: server=Node-7db5f7e8-106d-2d14-d633-62067f62c1d8 error="context deadline exceeded"
18:05.791 [DEBUG] TestAgent.server.memberlist.lan: memberlist: Failed ping: Node-7db5f7e8-106d-2d14-d633-62067f62c1d8 (timeout reached)
18:06.356 [WARN]  TestAgent: error getting server health from server: server=Node-7db5f7e8-106d-2d14-d633-62067f62c1d8 error="rpc error getting client: failed to get conn: dial tcp 127.0.0.1:0->127.0.0.1:20779: connect: connection refused"
18:07.290 [INFO]  TestAgent.server.memberlist.lan: memberlist: Suspect Node-7db5f7e8-106d-2d14-d633-62067f62c1d8 has failed, no acks received
18:07.356 [WARN]  TestAgent: error getting server health from server: server=Node-7db5f7e8-106d-2d14-d633-62067f62c1d8 error="context deadline exceeded"
18:07.791 [DEBUG] TestAgent.server.memberlist.lan: memberlist: Failed ping: Node-7db5f7e8-106d-2d14-d633-62067f62c1d8 (timeout reached)
18:08.291 [INFO]  TestAgent.server.memberlist.lan: memberlist: Marking Node-7db5f7e8-106d-2d14-d633-62067f62c1d8 as failed, suspect timeout reached (0 peer confirmations)
18:08.291 [INFO]  TestAgent.server.serf.lan: serf: EventMemberFailed: Node-7db5f7e8-106d-2d14-d633-62067f62c1d8 127.0.0.1
18:08.291 [INFO]  TestAgent.server: Removing LAN server: server="Node-7db5f7e8-106d-2d14-d633-62067f62c1d8 (Addr: tcp/127.0.0.1:20779) (DC: dc1)"
18:08.291 [INFO]  TestAgent.server: member failed, marking health critical: member=Node-7db5f7e8-106d-2d14-d633-62067f62c1d8
18:08.323 [INFO]  TestAgent: Force leaving node: node=Node-7db5f7e8-106d-2d14-d633-62067f62c1d8
18:08.323 [INFO]  TestAgent.server.serf.lan: serf: EventMemberLeave (forced): Node-7db5f7e8-106d-2d14-d633-62067f62c1d8 127.0.0.1
18:08.323 [INFO]  TestAgent: Requesting shutdown
18:08.323 [INFO]  TestAgent.server: shutting down server
18:08.324 [DEBUG] TestAgent.leader: stopping routine: routine="federation state pruning"
18:08.324 [DEBUG] TestAgent.leader: stopping routine: routine="intermediate cert renew watch"
18:08.324 [DEBUG] TestAgent.leader: stopping routine: routine="CA root pruning"
18:08.324 [DEBUG] TestAgent.leader: stopping routine: routine="federation state anti-entropy"
18:08.324 [WARN]  TestAgent.server.serf.lan: serf: Shutdown without a Leave
18:08.324 [DEBUG] TestAgent.server.usage_metrics: usage metrics reporter shutting down
18:08.324 [DEBUG] TestAgent.leader: stopped routine: routine="federation state pruning"
18:08.324 [DEBUG] TestAgent.leader: stopped routine: routine="intermediate cert renew watch"
18:08.324 [ERROR] TestAgent.server: error performing anti-entropy sync of federation state: error="context canceled"
18:08.324 [DEBUG] TestAgent.leader: stopped routine: routine="federation state anti-entropy"
18:08.324 [DEBUG] TestAgent.leader: stopped routine: routine="CA root pruning"
18:08.324 [DEBUG] TestAgent.server.autopilot: state update routine is now stopped
18:08.324 [DEBUG] TestAgent.server.autopilot: autopilot is now stopped
18:08.324 [WARN]  TestAgent.server.serf.wan: serf: Shutdown without a Leave
2020-11-20T16:18:08.324Z [INFO]  agent.router.manager: shutting down
2020-11-20T16:18:08.324Z [INFO]  agent.router.manager: shutting down
18:08.324 [INFO]  TestAgent: consul server down
18:08.324 [INFO]  TestAgent: shutdown complete
18:08.324 [INFO]  TestAgent: Stopping server: protocol=DNS address=127.0.0.1:20753 network=tcp
18:08.324 [INFO]  TestAgent: Stopping server: protocol=DNS address=127.0.0.1:20753 network=udp
18:08.324 [INFO]  TestAgent: Stopping server: address=127.0.0.1:20754 network=tcp protocol=http
18:08.824 [INFO]  TestAgent: Waiting for endpoints to shut down
18:08.824 [INFO]  TestAgent: Endpoints down
=== CONT  TestAgent_Leave
    retry.go:205: agent_endpoint_test.go:1809: got status "failed" want "left"
        agent_endpoint_test.go:1809: got status "alive" want "left"

[WARN] freeport: 4 out of 11 pending ports are still in use; something probably didn't wait around for the port to be closed!
2020-11-20T16:18:02.323Z [WARN]  agent: The 'acl_datacenter' field is deprecated. Use the 'primary_datacenter' field instead.
2020-11-20T16:18:02.323Z [WARN]  agent: bootstrap = true: do not enable unless necessary
2020-11-20T16:18:02.332Z [WARN]  agent.auto_config: The 'acl_datacenter' field is deprecated. Use the 'primary_datacenter' field instead.
2020-11-20T16:18:02.332Z [WARN]  agent.auto_config: bootstrap = true: do not enable unless necessary
18:02.334 [INFO]  TestAgent.server.raft: initial configuration: index=1 servers="[{Suffrage:Voter ID:0c107b94-e97a-54c8-8fff-8051dc797939 Address:127.0.0.1:20772}]"
18:02.334 [INFO]  TestAgent.server.raft: entering follower state: follower="Node at 127.0.0.1:20772 [Follower]" leader=
18:02.334 [INFO]  TestAgent.server.serf.wan: serf: EventMemberJoin: Node-0c107b94-e97a-54c8-8fff-8051dc797939.dc1 127.0.0.1
18:02.335 [INFO]  TestAgent.server.serf.lan: serf: EventMemberJoin: Node-0c107b94-e97a-54c8-8fff-8051dc797939 127.0.0.1
2020-11-20T16:18:02.335Z [INFO]  agent.router: Initializing LAN area manager
18:02.335 [INFO]  TestAgent.server: Handled event for server in area: event=member-join server=Node-0c107b94-e97a-54c8-8fff-8051dc797939.dc1 area=wan
18:02.335 [INFO]  TestAgent.server: Adding LAN server: server="Node-0c107b94-e97a-54c8-8fff-8051dc797939 (Addr: tcp/127.0.0.1:20772) (DC: dc1)"
18:02.335 [INFO]  TestAgent: Started DNS server: address=127.0.0.1:20767 network=udp
18:02.335 [INFO]  TestAgent: Started DNS server: address=127.0.0.1:20767 network=tcp
18:02.336 [INFO]  TestAgent: Starting server: address=127.0.0.1:20768 network=tcp protocol=http
18:02.336 [WARN]  TestAgent: DEPRECATED Backwards compatibility with pre-1.9 metrics enabled. These metrics will be removed in a future version of Consul. Set `telemetry { disable_compat_1.9 = true }` to disable them.
18:02.336 [INFO]  TestAgent: started state syncer
18:02.336 [INFO]  TestAgent: Started gRPC server: address=127.0.0.1:20773 network=tcp
18:02.385 [DEBUG] TestAgent.server: Cannot upgrade to new ACLs: leaderMode=3 mode=2 found=true leader=
18:02.398 [WARN]  TestAgent.server.raft: heartbeat timeout reached, starting election: last-leader=
18:02.398 [INFO]  TestAgent.server.raft: entering candidate state: node="Node at 127.0.0.1:20772 [Candidate]" term=2
18:02.398 [DEBUG] TestAgent.server.raft: votes: needed=1
18:02.398 [DEBUG] TestAgent.server.raft: vote granted: from=0c107b94-e97a-54c8-8fff-8051dc797939 term=2 tally=1
18:02.398 [INFO]  TestAgent.server.raft: election won: tally=1
18:02.398 [INFO]  TestAgent.server.raft: entering leader state: leader="Node at 127.0.0.1:20772 [Leader]"
18:02.399 [INFO]  TestAgent.server: cluster leadership acquired
18:02.399 [INFO]  TestAgent.server: New leader elected: payload=Node-0c107b94-e97a-54c8-8fff-8051dc797939
18:02.399 [INFO]  TestAgent.server: initializing acls
18:02.399 [INFO]  TestAgent.server: Created ACL 'global-management' policy
18:02.399 [WARN]  TestAgent.server: Configuring a non-UUID master token is deprecated
18:02.399 [INFO]  TestAgent.server: Bootstrapped ACL master token from configuration
18:02.400 [INFO]  TestAgent.server: Created ACL anonymous token from configuration
18:02.400 [INFO]  TestAgent.leader: started routine: routine="legacy ACL token upgrade"
18:02.400 [INFO]  TestAgent.leader: started routine: routine="acl token reaping"
18:02.400 [INFO]  TestAgent.server.serf.lan: serf: EventMemberUpdate: Node-0c107b94-e97a-54c8-8fff-8051dc797939
18:02.400 [INFO]  TestAgent.server.serf.wan: serf: EventMemberUpdate: Node-0c107b94-e97a-54c8-8fff-8051dc797939.dc1
18:02.400 [INFO]  TestAgent.server: Updating LAN server: server="Node-0c107b94-e97a-54c8-8fff-8051dc797939 (Addr: tcp/127.0.0.1:20772) (DC: dc1)"
18:02.400 [INFO]  TestAgent.server: Handled event for server in area: event=member-update server=Node-0c107b94-e97a-54c8-8fff-8051dc797939.dc1 area=wan
18:02.401 [DEBUG] TestAgent.server.autopilot: autopilot is now running
18:02.401 [DEBUG] TestAgent.server.autopilot: state update routine is now running
18:02.401 [DEBUG] connect.ca.consul: consul CA provider configured: id=07:80:c8:de:f6:41:86:29:8f:9c:b8:17:d6:48:c2:d5:c5:5c:7f:0c:03:f7:cf:97:5a:a7:c1:68:aa:23:ae:81 is_primary=true
18:02.402 [INFO]  TestAgent.server.connect: initialized primary datacenter CA with provider: provider=consul
18:02.402 [INFO]  TestAgent.leader: started routine: routine="federation state anti-entropy"
18:02.402 [INFO]  TestAgent.leader: started routine: routine="federation state pruning"
18:02.402 [INFO]  TestAgent.leader: started routine: routine="intermediate cert renew watch"
18:02.402 [INFO]  TestAgent.leader: started routine: routine="CA root pruning"
18:02.402 [DEBUG] TestAgent.server: successfully established leadership: duration=3.277798ms
18:02.402 [INFO]  TestAgent.server: member joined, marking health alive: member=Node-0c107b94-e97a-54c8-8fff-8051dc797939
18:02.471 [DEBUG] TestAgent.acl: dropping node from result due to ACLs: node=Node-0c107b94-e97a-54c8-8fff-8051dc797939
18:02.471 [DEBUG] TestAgent.acl: dropping node from result due to ACLs: node=Node-0c107b94-e97a-54c8-8fff-8051dc797939
18:02.472 [INFO]  TestAgent.server: server starting leave
18:02.472 [INFO]  TestAgent.server.serf.wan: serf: EventMemberLeave: Node-0c107b94-e97a-54c8-8fff-8051dc797939.dc1 127.0.0.1
18:02.472 [INFO]  TestAgent.server: Handled event for server in area: event=member-leave server=Node-0c107b94-e97a-54c8-8fff-8051dc797939.dc1 area=wan
2020-11-20T16:18:02.472Z [INFO]  agent.router.manager: shutting down
18:02.725 [INFO]  TestAgent.server: federation state anti-entropy synced
18:02.762 [DEBUG] TestAgent: Skipping remote check since it is managed automatically: check=serfHealth
18:02.762 [INFO]  TestAgent: Synced node info
18:02.762 [DEBUG] TestAgent: Node info in sync
18:05.253 [DEBUG] TestAgent: Skipping remote check since it is managed automatically: check=serfHealth
18:05.253 [DEBUG] TestAgent: Node info in sync
18:05.472 [INFO]  TestAgent.server.serf.lan: serf: EventMemberLeave: Node-0c107b94-e97a-54c8-8fff-8051dc797939 127.0.0.1
18:05.472 [INFO]  TestAgent.server: Removing LAN server: server="Node-0c107b94-e97a-54c8-8fff-8051dc797939 (Addr: tcp/127.0.0.1:20772) (DC: dc1)"
18:05.472 [WARN]  TestAgent.server: deregistering self should be done by follower: name=Node-0c107b94-e97a-54c8-8fff-8051dc797939
18:08.472 [INFO]  TestAgent.server: Waiting to drain RPC traffic: drain_time=5s
18:12.401 [DEBUG] TestAgent.server.autopilot: will not remove server as its removal would be unsafe due to affectingas removal of a majority or servers is not safe: id=0c107b94-e97a-54c8-8fff-8051dc797939
18:13.472 [INFO]  TestAgent: Requesting shutdown
18:13.472 [INFO]  TestAgent.server: shutting down server
18:13.472 [DEBUG] TestAgent.leader: stopping routine: routine="intermediate cert renew watch"
18:13.472 [DEBUG] TestAgent.leader: stopping routine: routine="CA root pruning"
18:13.472 [DEBUG] TestAgent.leader: stopping routine: routine="legacy ACL token upgrade"
18:13.472 [DEBUG] TestAgent.leader: stopping routine: routine="acl token reaping"
18:13.472 [DEBUG] TestAgent.leader: stopping routine: routine="federation state anti-entropy"
18:13.472 [DEBUG] TestAgent.leader: stopping routine: routine="federation state pruning"
18:13.472 [DEBUG] TestAgent.leader: stopped routine: routine="acl token reaping"
18:13.473 [DEBUG] TestAgent.server.usage_metrics: usage metrics reporter shutting down
18:13.473 [DEBUG] TestAgent.leader: stopped routine: routine="intermediate cert renew watch"
18:13.473 [DEBUG] TestAgent.leader: stopped routine: routine="CA root pruning"
18:13.473 [DEBUG] TestAgent.leader: stopped routine: routine="legacy ACL token upgrade"
18:13.473 [ERROR] TestAgent.server: error performing anti-entropy sync of federation state: error="context canceled"
18:13.473 [DEBUG] TestAgent.leader: stopped routine: routine="federation state anti-entropy"
18:13.473 [DEBUG] TestAgent.server.autopilot: state update routine is now stopped
18:13.473 [DEBUG] TestAgent.leader: stopped routine: routine="federation state pruning"
18:13.473 [DEBUG] TestAgent.server.autopilot: autopilot is now stopped
2020-11-20T16:18:13.473Z [INFO]  agent.router.manager: shutting down
18:13.473 [INFO]  TestAgent: consul server down
18:13.473 [INFO]  TestAgent: shutdown complete
18:13.473 [INFO]  TestAgent: Stopping server: protocol=DNS address=127.0.0.1:20767 network=tcp
18:13.473 [INFO]  TestAgent: Stopping server: protocol=DNS address=127.0.0.1:20767 network=udp
18:13.473 [INFO]  TestAgent: Stopping server: address=127.0.0.1:20768 network=tcp protocol=http
18:13.973 [INFO]  TestAgent: Waiting for endpoints to shut down
18:13.973 [INFO]  TestAgent: Endpoints down
--- FAIL: TestAgent_Leave (11.91s)