rpc: cross-peer "subscribe call failed" due to ACL not found
- Dominant language
- Go
- Stars
- 30.1k
- Forks
- 4.6k
- Avg merge
- 1d 18h
- Merged PRs (30d)
- 39
Description
#### Overview of the Issue
The local Consul agent emits errors that it is unable to subscribe to the health of services in a peered cluster.
```jsonld
{"@level":"error","@message":"subscribe call failed","@module":"agent.rpcclient.health","@timestamp":"2025-04-22T11:14:16.667985Z","err":"rpc error: code = Unknown desc = ACL not found","error":"rpc error: code = Unknown desc = ACL not found","failure_count":11,"key":"rabbitmq","topic":2}
{"@level":"error","@message":"subscribe call failed","@module":"agent.rpcclient.health","@timestamp":"2025-04-22T11:14:18.230787Z","err":"rpc error: code = Unknown desc = ACL not found","error":"rpc error: code = Unknown desc = ACL not found","failure_count":11,"key":"minio-console","topic":2}
{"@level":"error","@message":"subscribe call failed","@module":"agent.rpcclient.health","@timestamp":"2025-04-22T11:14:18.427128Z","err":"rpc error: code = Unknown desc = ACL not found","error":"rpc error: code = Unknown desc = ACL not found","failure_count":11,"key":"libraesva-api","topic":2}
{"@level":"error","@message":"subscribe call failed","@module":"agent.rpcclient.health","@timestamp":"2025-04-22T11:14:18.706068Z","err":"rpc error: code = Unknown desc = ACL not found","error":"rpc error: code = Unknown desc = ACL not found","failure_count":11,"key":"surrealdb","topic":2}
```
This appears 100% of the time (for every imported service, this warning appears for `failure_count` 1-20). This appears on every Consul node.
---
#### Reproduction Steps
1. Have two clusters
2. Enable cluster peering, setup MeshGateway mode to `remote`, start mesh gateways - the usual setup
3. Allow everything via intentions
4. Enable ACLs on both clusters, NOT defining `primary_datacenter`
5. Run a service with an envoy sidecar for Consul Connect
### Consul info for both Client and Server
Client info
```
agent:
check_monitors = 0
check_ttls = 2
checks = 9
services = 8
build:
prerelease = rc1
revision = d63a79d1
version = 1.21.0
version_metadata =
consul:
acl = enabled
known_servers = 3
server = false
runtime:
arch = amd64
cpu_count = 4
goroutines = 1024
max_procs = 4
os = linux
version = go1.23.6
serf_lan:
coordinate_resets = 0
encrypted = true
event_queue = 0
event_time = 8
failed = 0
health_score = 0
intent_queue = 0
left = 0
member_time = 138642
members = 11
query_queue = 0
query_time = 1
```
```
acl {
enabled = true
default_policy = "deny"
enable_token_persistence = true
tokens = {
default = "some-token"
}
}
log_json = true
connect {
enabled = true
}
ports {
grpc = 8502
}
bind_addr = "172.18.1.102"
addresses {
grpc = "127.0.0.1"
grpc_tls = "172.18.1.102"
dns = "172.18.1.102"
}
node_name = "hashivault02-del"
datacenter = "delmenhorst"
performance {
raft_multiplier = 1
}
tls {
https {
verify_incoming = false
verify_outgoing = true
ca_file = "/etc/consul.d/ca.pem"
}
internal_rpc {
verify_incoming = true
verify_outgoing = true
ca_file = "/etc/consul.d/ca.pem"
verify_server_hostname = true
}
}
auto_encrypt {
tls = true
}
data_dir = "/opt/consul"
ui_config {
enabled = true
}
server = false
retry_join = [ "consul-del.q-mex.net" ]
recursors = [ "127.0.0.53" ]
```
Server info
```
agent:
check_monitors = 0
check_ttls = 1
checks = 20
services = 16
build:
prerelease = rc1
revision = d63a79d1
version = 1.21.0
version_metadata =
consul:
acl = enabled
known_servers = 3
server = false
runtime:
arch = amd64
cpu_count = 6
goroutines = 947
max_procs = 6
os = linux
version = go1.23.6
serf_lan:
coordinate_resets = 0
encrypted = true
event_queue = 0
event_time = 8
failed = 0
health_score = 0
intent_queue = 0
left = 0
member_time = 138642
members = 11
query_queue = 0
query_time = 1
```
```
acl {
enabled = true
default_policy = "deny"
enable_token_persistence = true
tokens = {
default = "some-token"
}
}
log_json = true
connect {
enabled = true
}
ports {
https = 8501
grpc = 8502
}
bind_addr = "172.18.1.232"
client_addr = "172.18.1.232"
advertise_addr = "172.18.1.232"
node_name = "mini-ubuntu-consul-del"
datacenter = "delmenhorst"
performance {
raft_multiplier = 1
}
tls {
https {
verify_incoming = false
verify_outgoing = true
ca_file = "/etc/consul.d/ca.pem"
cert_file = "/etc/consul.d/agent.crt"
key_file = "/etc/consul.d/agent.key"
}
internal_rpc {
verify_incoming = true
verify_outgoing = true
ca_file = "/etc/consul.d/ca.pem"
cert_file = "/etc/consul.d/agent.crt"
key_file = "/etc/consul.d/agent.key"
verify_server_hostname = true
}
}
auto_encrypt {
allow_tls = true
}
data_dir = "/opt/consul"
ui_config {
enabled = true
}
server = true
bootstrap_expect = 3
retry_join = [ "consul-del.q-mex.net" ]
recursors = [ "127.0.0.53" ]
```
### Operating system and Environment details
Ubuntu 24.04.2 LTS on amd64
### Log Fragments
Client logs:
```
2025-04-22T11:23:13.552Z [DEBUG] agent.client.memberlist.lan: memberlist: Initiating push/pull sync with: hashivault-server-del 172.18.1.100:8301
2025-04-22T11:23:13.976Z [DEBUG] agent: Check status updated: check=service:_nomad-task-819b2ddf-1b86-511a-a329-1b50da5a5ddf-group-web-k4577-fw-wesling-qr-code-landing-page-80-sidecar-proxy:2 status=passing
2025-04-22T11:23:14.034Z [DEBUG] agent.http: Request finished: method=GET url=/v1/agent/checks from=127.0.0.1:39264 latency="490.419µs"
2025-04-22T11:23:14.035Z [DEBUG] agent: warning: request content-type is not supported: request-path=/v1/agent/checks
2025-04-22T11:23:14.221Z [DEBUG] agent.dns: request served from client: name=q-sse.virtual.consul. type=AAAA class=IN latency=1.66471ms client=172.26.64.51:51532 client_network=udp
2025-04-22T11:23:14.222Z [DEBUG] agent.dns: request served from client: name=q-sse.virtual.consul. type=A class=IN latency=1.61546ms client=172.26.64.51:51358 client_network=udp
2025-04-22T11:23:14.330Z [TRACE] agent.grpc.balancer: witnessed RPC error: target=consul://delmenhorst.505ed1cf-02db-cb61-9511-6905d80fcbbe/server.delmenhorst server=delmenhorst-172.18.1.233:8300 error="rpc error: code = Unknown desc = ACL not found"
2025-04-22T11:23:14.330Z [DEBUG] agent.grpc.balancer: switching server: target=consul://delmenhorst.505ed1cf-02db-cb61-9511-6905d80fcbbe/server.delmenhorst from=delmenhorst-172.18.1.233:8300 to=delmenhorst-172.18.1.231:8300
2025-04-22T11:23:14.331Z [TRACE] agent: [core][Channel #1 SubChannel #121960] Subchannel created
2025-04-22T11:23:14.331Z [TRACE] agent: [core][Channel #1] Channel Connectivity change to CONNECTING
2025-04-22T11:23:14.331Z [TRACE] agent: [core][Channel #1 SubChannel #121958] Subchannel Connectivity change to SHUTDOWN
2025-04-22T11:23:14.331Z [TRACE] agent: [core][Channel #1 SubChannel #121958] Subchannel deleted
2025-04-22T11:23:14.331Z [ERROR] agent.rpcclient.health: subscribe call failed: err="rpc error: code = Unknown desc = ACL not found" failure_count=17 key=vault topic=ServiceHealthConnect error="rpc error: code = Unknown desc = ACL not found"
2025-04-22T11:23:14.331Z [TRACE] agent: [core][Channel #1 SubChannel #121960] Subchannel Connectivity change to CONNECTING
2025-04-22T11:23:14.331Z [TRACE] agent: [core][Channel #1 SubChannel #121960] Subchannel picks a new address "delmenhorst-172.18.1.231:8300" to connect
2025-04-22T11:23:14.331Z [TRACE] agent.grpc.balancer: sub-connection state changed: target=consul://delmenhorst.505ed1cf-02db-cb61-9511-6905d80fcbbe/server.delmenhorst server=delmenhorst-172.18.1.231:8300 state=CONNECTING
2025-04-22T11:23:14.341Z [TRACE] agent: [core][Channel #1 SubChannel #121960] Subchannel Connectivity change to READY
2025-04-22T11:23:14.341Z [TRACE] agent.grpc.balancer: sub-connection state changed: target=consul://delmenhorst.505ed1cf-02db-cb61-9511-6905d80fcbbe/server.delmenhorst server=delmenhorst-172.18.1.231:8300 state=READY
2025-04-22T11:23:14.341Z [TRACE] agent: [core][Channel #1] Channel Connectivity change to READY
2025-04-22T11:23:14.344Z [DEBUG] agent.dns: request served from client: name=surrealdb.virtual.consul. type=AAAA class=IN latency=1.596348ms client=172.26.64.51:59612 client_network=udp
2025-04-22T11:23:14.347Z [DEBUG] agent.dns: request served from client: name=minio-console.virtual.consul. type=AAAA class=IN latency=1.488765ms client=172.26.64.51:59612 client_network=udp
2025-04-22T11:23:14.347Z [DEBUG] agent.dns: request served from client: name=q-telecom-public-api.virtual.cluster-bremen.consul. type=AAAA class=IN latency=1.54337ms client=172.26.64.51:59612 client_network=udp
2025-04-22T11:23:14.347Z [DEBUG] agent.dns: request served from client: name=libraesva-api.virtual.consul. type=AAAA class=IN latency=1.5466ms client=172.26.64.51:59612 client_network=udp
2025-04-22T11:23:14.347Z [DEBUG] agent.dns: request served from client: name=q-gateway--manager.virtual.consul. type=AAAA class=IN latency=1.874442ms client=172.26.64.51:59612 client_network=udp
2025-04-22T11:23:14.347Z [DEBUG] agent.dns: request served from client: name=q-ots.virtual.cluster-bremen.consul. type=AAAA class=IN latency=1.930861ms client=172.26.64.51:59612 client_network=udp
2025-04-22T11:23:14.347Z [DEBUG] agent.dns: request served from client: name=q-redirect-service.virtual.consul. type=AAAA class=IN latency=1.830468ms client=172.26.64.51:59612 client_network=udp
2025-04-22T11:23:14.348Z [DEBUG] agent.dns: request served from client: name=libraesva-api.virtual.cluster-bremen.consul. type=AAAA class=IN latency=2.426868ms client=172.26.64.51:59612 client_network=udp
2025-04-22T11:23:14.348Z [DEBUG] agent.dns: request served from client: name=minio-console.virtual.cluster-bremen.consul. type=AAAA class=IN latency=2.479555ms client=172.26.64.51:59612 client_network=udp
...
2025-04-22T11:23:17.362Z [DEBUG] agent.dns: request served from client: name=fin-api.virtual.cluster-bremen.consul. type=AAAA class=IN latency=1.929477ms client=172.26.64.51:59612 client_network=udp
2025-04-22T11:23:17.362Z [DEBUG] agent.dns: request served from client: name=update-gateway.virtual.consul. type=AAAA class=IN latency=1.401636ms client=172.26.64.51:59612 client_network=udp
2025-04-22T11:23:17.362Z [DEBUG] agent.dns: request served from client: name=q-sms.virtual.consul. type=AAAA class=IN latency=2.049396ms client=172.26.64.51:59612 client_network=udp
2025-04-22T11:23:17.363Z [DEBUG] agent.dns: request served from client: name=q-identity.virtual.consul. type=AAAA class=IN latency=2.060294ms client=172.26.64.51:59612 client_network=udp
2025-04-22T11:23:17.363Z [DEBUG] agent.dns: request served from client: name=q-sse.virtual.consul. type=AAAA class=IN latency=2.03504ms client=172.26.64.51:59612 client_network=udp
2025-04-22T11:23:17.519Z [TRACE] agent.proxycfg.agent-state: syncing proxy services from local state
2025-04-22T11:23:17.640Z [TRACE] agent.grpc.balancer: witnessed RPC error: target=consul://delmenhorst.505ed1cf-02db-cb61-9511-6905d80fcbbe/server.delmenhorst server=delmenhorst-172.18.1.233:8300 error="rpc error: code = Unknown desc = ACL not found"
2025-04-22T11:23:17.640Z [DEBUG] agent.grpc.balancer: switching server: target=consul://delmenhorst.505ed1cf-02db-cb61-9511-6905d80fcbbe/server.delmenhorst from=delmenhorst-172.18.1.233:8300 to=delmenhorst-172.18.1.231:8300
2025-04-22T11:23:17.640Z [TRACE] agent: [core][Channel #1 SubChannel #121966] Subchannel created
2025-04-22T11:23:17.640Z [TRACE] agent: [core][Channel #1] Channel Connectivity change to CONNECTING
2025-04-22T11:23:17.640Z [TRACE] agent: [core][Channel #1 SubChannel #121964] Subchannel Connectivity change to SHUTDOWN
2025-04-22T11:23:17.640Z [TRACE] agent: [core][Channel #1 SubChannel #121964] Subchannel deleted
2025-04-22T11:23:17.640Z [TRACE] agent: [core][Channel #1 SubChannel #121966] Subchannel Connectivity change to CONNECTING
...
2025-04-22T11:23:18.365Z [DEBUG] agent.dns: request served from client: name=q-sms.virtual.consul. type=AAAA class=IN latency=1.76792ms client=172.26.64.51:59612 client_network=udp
2025-04-22T11:23:18.365Z [DEBUG] agent.dns: request served from client: name=update-gateway.virtual.consul. type=AAAA class=IN latency=1.837054ms client=172.26.64.51:59612 client_network=udp
2025-04-22T11:23:18.366Z [DEBUG] agent.dns: request served from client: name=surrealdb.virtual.cluster-bremen.consul. type=AAAA class=IN latency=2.029057ms client=172.26.64.51:59612 client_network=udp
2025-04-22T11:23:18.366Z [DEBUG] agent.dns: request served from client: name=q-sse.virtual.consul. type=AAAA class=IN latency=2.196877ms client=172.26.64.51:59612 client_network=udp
2025-04-22T11:23:18.366Z [DEBUG] agent.dns: request served from client: name=q-redirect-service.virtual.cluster-bremen.consul. type=AAAA class=IN latency=1.993066ms client=172.26.64.51:59612 client_network=udp
2025-04-22T11:23:18.366Z [DEBUG] agent.dns: request served from client: name=q-identity.virtual.consul. type=AAAA class=IN latency=2.270053ms client=172.26.64.51:59612 client_network=udp
2025-04-22T11:23:18.366Z [DEBUG] agent.dns: request served from client: name=minio-api.virtual.cluster-bremen.consul. type=AAAA class=IN latency=2.361959ms client=172.26.64.51:59612 client_network=udp
2025-04-22T11:23:18.411Z [TRACE] agent.grpc.balancer: witnessed RPC error: target=consul://delmenhorst.505ed1cf-02db-cb61-9511-6905d80fcbbe/server.delmenhorst server=delmenhorst-172.18.1.231:8300 error="rpc error: code = Unknown desc = ACL not found"
2025-04-22T11:23:18.411Z [DEBUG] agent.grpc.balancer: switching server: target=consul://delmenhorst.505ed1cf-02db-cb61-9511-6905d80fcbbe/server.delmenhorst from=delmenhorst-172.18.1.231:8300 to=delmenhorst-172.18.1.232:8300
2025-04-22T11:23:18.411Z [TRACE] agent: [core][Channel #1 SubChannel #121968] Subchannel created
2025-04-22T11:23:18.411Z [TRACE] agent: [core][Channel #1] Channel Connectivity change to CONNECTING
2025-04-22T11:23:18.411Z [TRACE] agent: [core][Channel #1 SubChannel #121966] Subchannel Connectivity change to SHUTDOWN
2025-04-22T11:23:18.411Z [TRACE] agent: [core][Channel #1 SubChannel #121966] Subchannel deleted
2025-04-22T11:23:18.411Z [TRACE] agent: [core][Channel #1 SubChannel #121968] Subchannel Connectivity change to CONNECTING
2025-04-22T11:23:18.411Z [TRACE] agent: [core][Channel #1 SubChannel #121968] Subchannel picks a new address "delmenhorst-172.18.1.232:8300" to connect
2025-04-22T11:23:18.411Z [TRACE] agent.grpc.balancer: sub-connection state changed: target=consul://delmenhorst.505ed1cf-02db-cb61-9511-6905d80fcbbe/server.delmenhorst server=delmenhorst-172.18.1.232:8300 state=CONNECTING
2025-04-22T11:23:18.422Z [TRACE] agent: [core][Channel #1 SubChannel #121968] Subchannel Connectivity change to READY
2025-04-22T11:23:18.422Z [TRACE] agent.grpc.balancer: sub-connection state changed: target=consul://delmenhorst.505ed1cf-02db-cb61-9511-6905d80fcbbe/server.delmenhorst server=delmenhorst-172.18.1.232:8300 state=READY
2025-04-22T11:23:18.422Z [TRACE] agent: [core][Channel #1] Channel Connectivity change to READY
2025-04-22T11:23:19.046Z [DEBUG] agent.http: Request finished: method=GET url=/v1/agent/checks from=127.0.0.1:39264 latency="434.822µs"
2025-04-22T11:23:19.046Z [DEBUG] agent: warning: request content-type is not supported: request-path=/v1/agent/checks
2025-04-22T11:23:19.241Z [DEBUG] agent.dns: request served from client: name=q-sse.virtual.consul. type=A class=IN latency=1.935026ms client=172.26.64.51:50123 client_network=udp
```
Server Logs (local cluster) - note the time is a bit later, but the issue keeps persisting/logging, so we can clearly see the `new subscription` and `subscription closed` in the same instant.
```
2025-04-22T11:24:57.897Z [TRACE] agent.server.grpc-api.subscription: new subscription: dc=delmenhorst key=vault namespace="" partition="" peer=cluster-bremen request_index=1877304 stream_id=58be0396-fc9c-0fd6-1ba2-03ed2a97a1d4 topic=ServiceHealthConnect
2025-04-22T11:24:57.897Z [TRACE] agent.server.grpc-api.subscription: subscription closed: dc=delmenhorst key=vault namespace="" partition="" peer=cluster-bremen request_index=1877304 stream_id=58be0396-fc9c-0fd6-1ba2-03ed2a97a1d4 topic=ServiceHealthConnect
2025-04-22T11:24:58.199Z [TRACE] agent.server: rpc_server_call: method=Status.RaftStats errored=false request_type=read rpc_type=net/rpc leader=false
2025-04-22T11:24:58.489Z [TRACE] agent.server.grpc-api.subscription: new subscription: dc=delmenhorst key=surrealdb namespace="" partition="" peer=cluster-bremen request_index=1877274 stream_id=d3cbeee2-fd4f-b16e-1614-42b70237d08f topic=ServiceHealthConnect
2025-04-22T11:24:58.489Z [TRACE] agent.server.grpc-api.subscription: subscription closed: dc=delmenhorst key=surrealdb namespace="" partition="" peer=cluster-bremen request_index=1877274 stream_id=d3cbeee2-fd4f-b16e-1614-42b70237d08f topic=ServiceHealthConnect
2025-04-22T11:24:58.742Z [TRACE] agent.server: rpc_server_call: method=Status.RaftStats errored=false request_type=read rpc_type=net/rpc leader=false
2025-04-22T11:24:58.779Z [TRACE] agent.server: rpc_server_call: method=Status.RaftStats errored=false request_type=read rpc_type=net/rpc leader=false
2025-04-22T11:24:59.740Z [TRACE] agent.server.grpc-api.subscription: new subscription: dc=delmenhorst key=surrealdb namespace="" partition="" peer=cluster-bremen request_index=1877274 stream_id=65c9e3c8-3ff0-545a-98f8-2e8fc9f550ed topic=ServiceHealthConnect
2025-04-22T11:24:59.740Z [TRACE] agent.server.grpc-api.subscription: subscription closed: dc=delmenhorst key=surrealdb namespace="" partition="" peer=cluster-bremen request_index=1877274 stream_id=65c9e3c8-3ff0-545a-98f8-2e8fc9f550ed topic=ServiceHealthConnect
2025-04-22T11:25:00.005Z [TRACE] agent.server.grpc-api.subscription: new subscription: dc=delmenhorst key=k4577-fw-wesling-qr-code-landing-page namespace="" partition="" peer=cluster-bremen request_index=1877244 stream_id=3f3be72e-65cb-2a78-905f-594a0b1787d7 topic=ServiceHealthConnect
2025-04-22T11:25:00.005Z [TRACE] agent.server.grpc-api.subscription: subscription closed: dc=delmenhorst key=k4577-fw-wesling-qr-code-landing-page namespace="" partition="" peer=cluster-bremen request_index=1877244 stream_id=3f3be72e-65cb-2a78-905f-594a0b1787d7 topic=ServiceHealthConnect
2025-04-22T11:25:00.065Z [TRACE] agent.server: rpc_server_call: method=Coordinate.Update errored=false
```
Server logs (peered cluster):
```
Nothing relevant.
```
Client agent logs (on the node that runs the mesh gateway)
```
Nothing relevant.
```
---
# Other findings
- I can call the local agent HTTP API and get reliable results on `/v1/health/service/myservice?peer=cluster-bremen&index=12345&wait=2s` - this seems to not cause any errors.
- The rpc call that has issues seems to come from Envoy (or from the Consul part that generates the config for Envoy).
- The ACL errors keep coming in (higher `failure_count`) even after having stopped the Nomad Job which had the Consul Connect envoy sidecar task. Is there something not quite being tidied up correctly?
Contributor guide
Research direction
Start with the agent.rpcclient.health subscribe errors and the agent.grpc.balancer ACL-not-found traces, then reproduce the two-cluster peering setup with ACLs enabled and no primary_datacenter. Trace the cross-peer health subscription path and identify why imported services cannot subscribe; done means the reproduced setup no longer emits these failures.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- go
- Domain
- distributed-systems, security
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Needs clarification
- Newbie friendliness
- 35/100