Unflake TestAgent_Service_Reap in resource-constrained envs
- Dominant language
- Go
- Stars
- 30.1k
- Forks
- 4.6k
- Avg merge
- 2d 6h
- Merged PRs (30d)
- 43
Description
https://github.com/hashicorp/consul/blob/ba8fd8296fe7c69615d0d27afdb2bbf71b6b32df/agent/agent_test.go#L2702
Running a local sample, getting a `should not have critical checks` response frequently. Easy to reproduce so far. Log results:
```
=== RUN TestAgent_Service_Reap
--- FAIL: TestAgent_Service_Reap (0.63s)
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.313971 [WARN] bootstrap = true: do not enable unless necessary
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.314150 [DEBUG] tlsutil: Update with version 1
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.314436 [DEBUG] tlsutil: OutgoingRPCWrapper with version 1
writer.go:21: 2020/01/21 11:45:08 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:242402b0-f1d5-f5b1-4e96-de10d2259fc0 Address:127.0.0.1:38062}]
writer.go:21: 2020/01/21 11:45:08 [INFO] raft: Node at 127.0.0.1:38062 [Follower] entering Follower state (Leader: "")
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.476698 [INFO] serf: EventMemberJoin: Node-242402b0-f1d5-f5b1-4e96-de10d2259fc0.dc1 127.0.0.1
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.477336 [INFO] serf: EventMemberJoin: Node-242402b0-f1d5-f5b1-4e96-de10d2259fc0 127.0.0.1
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.477432 [INFO] consul: Adding LAN server Node-242402b0-f1d5-f5b1-4e96-de10d2259fc0 (Addr: tcp/127.0.0.1:38062) (DC: dc1)
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.477465 [INFO] consul: Handled member-join event for server "Node-242402b0-f1d5-f5b1-4e96-de10d2259fc0.dc1" in area "wan"
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.477994 [INFO] agent: Started DNS server 127.0.0.1:38057 (udp)
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.478043 [INFO] agent: Started DNS server 127.0.0.1:38057 (tcp)
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.478789 [INFO] agent: Started HTTP server on 127.0.0.1:38058 (tcp)
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.478820 [INFO] agent: started state syncer
writer.go:21: 2020/01/21 11:45:08 [WARN] raft: Heartbeat timeout from "" reached, starting election
writer.go:21: 2020/01/21 11:45:08 [INFO] raft: Node at 127.0.0.1:38062 [Candidate] entering Candidate state in term 2
writer.go:21: 2020/01/21 11:45:08 [INFO] raft: Election won. Tally: 1
writer.go:21: 2020/01/21 11:45:08 [INFO] raft: Node at 127.0.0.1:38062 [Leader] entering Leader state
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.569329 [INFO] consul: cluster leadership acquired
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.569736 [INFO] consul: New leader elected: Node-242402b0-f1d5-f5b1-4e96-de10d2259fc0
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.654499 [DEBUG] 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 IsPrimary=true
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.731413 [INFO] connect: initialized primary datacenter CA with provider "consul"
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.731544 [INFO] leader: started CA root pruning routine
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.731768 [DEBUG] consul: Skipping self join check for "Node-242402b0-f1d5-f5b1-4e96-de10d2259fc0" since the cluster is too small
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.731866 [INFO] consul: member 'Node-242402b0-f1d5-f5b1-4e96-de10d2259fc0' joined, marking health alive
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.796362 [WARN] agent: Check "service:redis" missed TTL, is now critical
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.866819 [DEBUG] agent: Check "service:redis" status is now passing
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.894179 [WARN] agent: Check "service:redis" missed TTL, is now critical
require.go:738:
Error Trace: agent_test.go:2615
Error: "map[{service:redis {}}:%!s(*local.CheckState=&{0xc0000de820 {13799577988474185000 175127455928 0x98a0fe0} false false})]" should have 0 item(s), but has 1
Test: TestAgent_Service_Reap
Messages: should not have critical checks
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.897970 [INFO] agent: Requesting shutdown
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.898038 [INFO] consul: shutting down server
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.898091 [DEBUG] leader: stopping CA root pruning routine
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.898132 [WARN] serf: Shutdown without a Leave
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.898145 [ERR] agent: failed to sync remote state: No cluster leader
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.898142 [DEBUG] leader: stopped CA root pruning routine
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.918057 [WARN] serf: Shutdown without a Leave
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.931393 [INFO] manager: shutting down
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.931796 [INFO] agent: consul server down
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.931893 [INFO] agent: shutdown complete
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.931956 [INFO] agent: Stopping DNS server 127.0.0.1:38057 (tcp)
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.932102 [INFO] agent: Stopping DNS server 127.0.0.1:38057 (udp)
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.932249 [INFO] agent: Stopping HTTP server 127.0.0.1:38058 (tcp)
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.932457 [INFO] agent: Waiting for endpoints to shut down
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.932508 [INFO] agent: Endpoints down
=== RUN TestAgent_Service_Reap
--- FAIL: TestAgent_Service_Reap (0.60s)
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.947298 [WARN] bootstrap = true: do not enable unless necessary
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.947898 [DEBUG] tlsutil: Update with version 1
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:08.948150 [DEBUG] tlsutil: OutgoingRPCWrapper with version 1
writer.go:21: 2020/01/21 11:45:09 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:51a1fa36-9677-6629-87b5-3c7f7c6c56d9 Address:127.0.0.1:38068}]
writer.go:21: 2020/01/21 11:45:09 [INFO] raft: Node at 127.0.0.1:38068 [Follower] entering Follower state (Leader: "")
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.098939 [INFO] serf: EventMemberJoin: Node-51a1fa36-9677-6629-87b5-3c7f7c6c56d9.dc1 127.0.0.1
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.100121 [INFO] serf: EventMemberJoin: Node-51a1fa36-9677-6629-87b5-3c7f7c6c56d9 127.0.0.1
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.100282 [INFO] consul: Adding LAN server Node-51a1fa36-9677-6629-87b5-3c7f7c6c56d9 (Addr: tcp/127.0.0.1:38068) (DC: dc1)
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.100323 [INFO] consul: Handled member-join event for server "Node-51a1fa36-9677-6629-87b5-3c7f7c6c56d9.dc1" in area "wan"
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.100469 [INFO] agent: Started DNS server 127.0.0.1:38063 (udp)
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.100496 [INFO] agent: Started DNS server 127.0.0.1:38063 (tcp)
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.100858 [INFO] agent: Started HTTP server on 127.0.0.1:38064 (tcp)
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.100896 [INFO] agent: started state syncer
writer.go:21: 2020/01/21 11:45:09 [WARN] raft: Heartbeat timeout from "" reached, starting election
writer.go:21: 2020/01/21 11:45:09 [INFO] raft: Node at 127.0.0.1:38068 [Candidate] entering Candidate state in term 2
writer.go:21: 2020/01/21 11:45:09 [INFO] raft: Election won. Tally: 1
writer.go:21: 2020/01/21 11:45:09 [INFO] raft: Node at 127.0.0.1:38068 [Leader] entering Leader state
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.197518 [INFO] consul: cluster leadership acquired
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.197843 [INFO] consul: New leader elected: Node-51a1fa36-9677-6629-87b5-3c7f7c6c56d9
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.271719 [DEBUG] 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 IsPrimary=true
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.341434 [INFO] connect: initialized primary datacenter CA with provider "consul"
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.341521 [INFO] leader: started CA root pruning routine
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.341784 [DEBUG] consul: Skipping self join check for "Node-51a1fa36-9677-6629-87b5-3c7f7c6c56d9" since the cluster is too small
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.341879 [INFO] consul: member 'Node-51a1fa36-9677-6629-87b5-3c7f7c6c56d9' joined, marking health alive
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.381251 [DEBUG] agent: Skipping remote check "serfHealth" since it is managed automatically
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.393712 [WARN] agent: Check "service:redis" missed TTL, is now critical
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.408887 [INFO] agent: Synced service "redis"
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.408980 [DEBUG] agent: Check "service:redis" in sync
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.409022 [DEBUG] agent: Node info in sync
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.409106 [DEBUG] agent: Service "redis" in sync
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.409159 [DEBUG] agent: Check "service:redis" in sync
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.409195 [DEBUG] agent: Node info in sync
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.469582 [DEBUG] agent: Check "service:redis" status is now passing
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.498354 [WARN] agent: Check "service:redis" missed TTL, is now critical
require.go:738:
Error Trace: agent_test.go:2615
Error: "map[{service:redis {}}:%!s(*local.CheckState=&{0xc0000fd380 {13799577989152061824 175731581079 0x98a0fe0} false false})]" should have 0 item(s), but has 1
Test: TestAgent_Service_Reap
Messages: should not have critical checks
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.499493 [INFO] agent: Requesting shutdown
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.499570 [INFO] consul: shutting down server
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.499598 [DEBUG] leader: stopping CA root pruning routine
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.499628 [WARN] serf: Shutdown without a Leave
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.499724 [DEBUG] leader: stopped CA root pruning routine
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.518724 [WARN] serf: Shutdown without a Leave
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.531874 [INFO] manager: shutting down
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.532080 [INFO] agent: consul server down
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.532187 [INFO] agent: shutdown complete
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.532256 [INFO] agent: Stopping DNS server 127.0.0.1:38063 (tcp)
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.532410 [INFO] agent: Stopping DNS server 127.0.0.1:38063 (udp)
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.532516 [INFO] agent: Stopping HTTP server 127.0.0.1:38064 (tcp)
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.532668 [INFO] agent: Waiting for endpoints to shut down
log.go:172: TestAgent_Service_Reap - 2020/01/21 11:45:09.532756 [INFO] agent: Endpoints down
FAIL agent.TestAgent_Service_Reap (0.60s)
```
Contributor guide
Assessment
This issue has not been assessed yet.