Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[Unstable Tests] Unstable tests on Master #8686

Open
pierresouchay opened this issue Sep 15, 2020 · 2 comments
Open

[Unstable Tests] Unstable tests on Master #8686

pierresouchay opened this issue Sep 15, 2020 · 2 comments
Labels
theme/internal-cleanup Used to identify tech debt, testing improvements, code refactoring, and non-impactful optimization theme/testing Testing, and related enhancements

Comments

@pierresouchay
Copy link
Contributor

Here are 2 unstable tests I found while doing PR #8685 from master 86e7274

  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)
@pierresouchay pierresouchay mentioned this issue Sep 15, 2020
Merged
@jsosulska
Copy link
Contributor

Also mentioned here: #7520

@jsosulska jsosulska mentioned this issue Sep 17, 2020
Merged
@jsosulska jsosulska added theme/internal-cleanup Used to identify tech debt, testing improvements, code refactoring, and non-impactful optimization theme/testing Testing, and related enhancements labels Sep 17, 2020
@pierresouchay
Copy link
Contributor Author

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)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
theme/internal-cleanup Used to identify tech debt, testing improvements, code refactoring, and non-impactful optimization theme/testing Testing, and related enhancements
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@pierresouchay @jsosulska