error filling agent cache: Internal cache failure
- Dominant language
- Go
- Stars
- 30.1k
- Forks
- 4.6k
- Avg merge
- 2d 6h
- Merged PRs (30d)
- 43
Description
#### Overview of the Issue
Hello,
I have a nomad job with a connect enabled backend.
sometimes, It produces an error log in consul agent :
```
error filling agent cache: Internal cache failure: service '_nomad-task-XXX' not in agent state
```
#### Reproduction Steps
Here is an easy reproduction method
```
$ nomad -version
Nomad v0.12.4 (8efaee4ba5e9727ab323aaba2ac91c2d7b572d84)
$ consul -version
Consul v1.8.3
Revision a9322b9c7
Protocol 2 spoken by default, understands 2 to 3 (agent will automatically use protocol >2 when speaking to compatible agents)
```
Create the example nomad jobs
```
cat < backend.nomad
job "countdash" {
datacenters = ["dc1"]
group "api" {
network {
mode = "bridge"
}
service {
name = "count-api"
port = "9001"
connect {
sidecar_service {}
}
}
task "web" {
driver = "docker"
config {
image = "hashicorpnomad/counter-api:v1"
}
}
}
}
EOF
cat < batch_with_connect.nomad
job "batch_with_connect" {
datacenters = ["dc1"]
type = "batch"
periodic {
cron = "*/15 * * * * * *"
prohibit_overlap = true
}
group "batch_with_connect" {
network {
mode = "bridge"
}
service {
name = "count-dashboard"
port = "9002"
connect {
sidecar_service {
proxy {
upstreams {
destination_name = "count-api"
local_bind_port = 8080
}
}
}
}
}
task "echo" {
driver = "docker"
config {
image = "debian:10"
args = ["echo", "done"]
}
}
}
}
EOF
```
Start consul
```
consul agent -dev -log-level=TRACE 2>&1 | tee consul.log
```
Start nomad
```
sudo nomad agent -dev-connect -log-level=TRACE 2>&1 | tee nomad.log
```
Start backend job on nomad (wait it is fully started)
```
$ nomad job run backend.nomad
$ [ -z "$(curl -s http://127.0.0.1:8500/v1/agent/checks | grep Status | grep -v passing)" ] && echo OK
OK
```
Start batch job on nomad
```
$ nomad job run batch_with_connect.nomad
```
Wait an error in consul logs (job launches every 15 seconds)
```
grep "ERROR.*cache" consul.log
```
### Consul info for both Client and Server
Consul info
```
agent:
check_monitors = 0
check_ttls = 0
checks = 6
services = 6
build:
prerelease =
revision = a9322b9c
version = 1.8.3
consul:
acl = disabled
bootstrap = false
known_datacenters = 1
leader = true
leader_addr = 127.0.0.1:8300
server = true
raft:
applied_index = 44
commit_index = 44
fsm_pending = 0
last_contact = 0
last_log_index = 44
last_log_term = 2
last_snapshot_index = 0
last_snapshot_term = 0
latest_configuration = [{Suffrage:Voter ID:506cf337-31df-4815-01b0-90606fc638f6 Address:127.0.0.1:8300}]
latest_configuration_index = 0
num_peers = 0
protocol_version = 3
protocol_version_max = 3
protocol_version_min = 0
snapshot_version_max = 1
snapshot_version_min = 0
state = Leader
term = 2
runtime:
arch = amd64
cpu_count = 8
goroutines = 123
max_procs = 8
os = linux
version = go1.14.7
serf_lan:
coordinate_resets = 0
encrypted = false
event_queue = 1
event_time = 2
failed = 0
health_score = 0
intent_queue = 0
left = 0
member_time = 1
members = 1
query_queue = 0
query_time = 1
serf_wan:
coordinate_resets = 0
encrypted = false
event_queue = 0
event_time = 1
failed = 0
health_score = 0
intent_queue = 0
left = 0
member_time = 1
members = 1
query_queue = 0
query_time = 1
```
### Operating system and Environment details
Linux
### Log Fragments
Logs extract
```
2020-09-11T09:59:31.292+0200 [TRACE] agent.proxycfg: resetting watches for discovery chain: service_id=_nomad-task-4f11511e-782f-27e0-1480-c64812a66525-group-batch_with_connect-count-dashboard-9002-sidecar-proxy id=count-api
2020-09-11T09:59:31.292+0200 [TRACE] agent.proxycfg: initializing watch of target: service_id=_nomad-task-4f11511e-782f-27e0-1480-c64812a66525-group-batch_with_connect-count-dashboard-9002-sidecar-proxy upstream=count-api chain=count-api target=count-api.default.dc1 mesh-gateway-mode=
2020-09-11T09:59:31.341+0200 [DEBUG] agent.http: Request finished: method=GET url=/v1/agent/service/_nomad-task-4f11511e-782f-27e0-1480-c64812a66525-group-batch_with_connect-count-dashboard-9002-sidecar-proxy from=127.0.0.1:36134 latency=203.509µs
2020-09-11T09:59:32.223+0200 [DEBUG] agent: removed check: check=service:_nomad-task-4f11511e-782f-27e0-1480-c64812a66525-group-batch_with_connect-count-dashboard-9002-sidecar-proxy:1
2020-09-11T09:59:32.223+0200 [ERROR] agent.proxycfg: watch error: service_id=_nomad-task-4f11511e-782f-27e0-1480-c64812a66525-group-batch_with_connect-count-dashboard-9002-sidecar-proxy id=service-http-checks:_nomad-task-4f11511e-782f-27e0-1480-c64812a66525-group-batch_with_connect-count-dashboard-9002 error="error filling agent cache: Internal cache failure: service '_nomad-task-4f11511e-782f-27e0-1480-c64812a66525-group-batch_with_connect-count-dashboard-9002' not in agent state"
2020-09-11T09:59:32.223+0200 [DEBUG] agent: removed check: check=service:_nomad-task-4f11511e-782f-27e0-1480-c64812a66525-group-batch_with_connect-count-dashboard-9002-sidecar-proxy:2
2020-09-11T09:59:32.223+0200 [DEBUG] agent: removed service: service=_nomad-task-4f11511e-782f-27e0-1480-c64812a66525-group-batch_with_connect-count-dashboard-9002-sidecar-proxy
2020-09-11T09:59:32.223+0200 [ERROR] agent.proxycfg: watch error: service_id=_nomad-task-4f11511e-782f-27e0-1480-c64812a66525-group-batch_with_connect-count-dashboard-9002-sidecar-proxy id=service-http-checks:_nomad-task-4f11511e-782f-27e0-1480-c64812a66525-group-batch_with_connect-count-dashboard-9002 error="error filling agent cache: Internal cache failure: service '_nomad-task-4f11511e-782f-27e0-1480-c64812a66525-group-batch_with_connect-count-dashboard-9002' not in agent state"
2020-09-11T09:59:32.223+0200 [INFO] agent: Deregistered service: service=_nomad-task-4f11511e-782f-27e0-1480-c64812a66525-group-batch_with_connect-count-dashboard-9002-sidecar-proxy
```
Full logs
* nomad https://gist.github.com/saez0pub/b685e80830f269a8697f6f968923f928#file-nomad-log
* consul https://gist.github.com/saez0pub/b685e80830f269a8697f6f968923f928#file-consul-log
Contributor guide
Assessment
This issue has not been assessed yet.