Skip to content

proxycfg leaks a watcher goroutine per imported peered upstream on every peered-upstreams update #23931

Description

@EtienneBruines

Overview of the Issue

A client agent serving a transparent-proxy sidecar with cluster peering leaks one
watcher goroutine per imported peered upstream, on every peered-upstreams update, for
the lifetime of the process. On our cluster this reaches ~8000 goroutines within a few
hours and ends in the agent being OOM-killed.

handlerConnectProxy.handleUpdate re-runs setupWatchesForPeeredUpstream for every
imported service on every peered-upstreams update
(connect_proxy.go#L358-L377),
and that function has no "already watched" guard, passes the long-lived state context,
and records a nil cancel func
(connect_proxy.go#L270-L284):

err := s.dataSources.Health.Notify(ctx, &structs.ServiceSpecificRequest{...},
    upstreamPeerWatchIDPrefix+uid.String(), s.ch)
...
snapConnectProxy.PeerUpstreamEndpoints.InitWatch(uid, nil)

Each Health.Notify starts a goroutine in
submatview.Store.NotifyCallback
whose only exit is ctx.Err() != nil. Because the context is the state's own and the
stored cancel is nil, nothing can ever reclaim it — not the next update, and not
reconcilePeeringWatches, whose
CancelWatch
is a no-op against a nil cancel. So removing an imported service leaks too. Compare
watchUpstreamTarget, which does the same registration correctly: child context, real
cancel func stored.

A second, related defect.
state.Close
returns early once the run loop has stopped, and
Manager.register
replaces a stopped state without calling Close at all. state.run recovers panics,
which leaves the loop dead but every watch it registered still live and uncancelled;
local.Sync then recreates the state on its next resync ("recreate any terminated
watches"), so one recovered panic strands that proxy's entire watch set. We do not
observe this in production (zero unexpected panic while running proxycfg in our
logs) — reporting it because it is the same class of bug in the same recovery path.

Why this is filed separately from #23923. I originally reported it there, but the
evidence since says they are independent:

  • The leaking code is byte-identical in v1.21.0-rc2, v1.22.0, v1.22.3, v2.0.1,
    v2.0.3, v2.0.4 and main. It is not the 2.0.4 regression.
  • @sawall reports v2.0.4 giving i/o deadline reached errors #23923 at full strength with no goroutine growth at all. That is
    consistent: they have the EOF regression but no peering + transparent proxy, so this
    code path never runs for them.
  • This leak needs no EOF at all — any peered-upstreams index bump triggers it. v2.0.4 giving i/o deadline reached errors #23923
    plausibly raises the rate by churning peering streams, but is not the cause.

Reproduction Steps

Preconditions: transparent proxy mode (the peered-upstreams watch is only
registered in tproxy mode) and at least one service imported from a peer.

  1. Create two datacenters with a cluster peering connection between them, and export
    at least one service from the peer.
  2. On a client agent in the importing datacenter, register a connect sidecar with
    mode = "transparent" and no explicit upstreams, so its upstreams are inferred
    from the imported services.
  3. Poll /v1/agent/metrics for consul.runtime.num_goroutines, or take
    /debug/pprof/goroutine?debug=1 captures a few minutes apart.
  4. Observe a step function: flat, then a jump of (imported services x tproxy proxies)
    per query window, never coming back down, until the agent is OOM-killed.

The same thing is reproducible as two unit tests, both failing on v2.0.4 and main:

  1. Drive handlerConnectProxy.handleUpdate with three identical peered-upstreams
    events and count Health.Notify calls for one upstream: 3 registrations instead of
    1, all sharing a context that cannot be individually cancelled.
  2. Panic inside handleUpdate, wait for the run loop to exit, then call state.Close:
    the watch context is never cancelled.

Consul info for both Client and Server

Note on the client sample below: the affected client agents have since been patched, so
what is shown is a client in the exporting (peer) datacenter. It runs an otherwise
identical config, including one transparent-proxy sidecar, but imports no peered
services — and it does not leak (7 days uptime, zero restarts, no OOM). It is included
as a control. The affected agents were 2.0.4 (and previously 2.0.3) clients in the
importing datacenter, whose measurements are in Log Fragments below.

Client info
agent:
        check_monitors = 0
        check_ttls = 4
        checks = 34
        services = 27
build:
        prerelease =
        revision = d0f2be93
        version = 2.0.3
        version_metadata =
consul:
        acl = enabled
        known_servers = 3
        server = false
runtime:
        arch = amd64
        cpu_count = 4
        goroutines = 1012
        max_procs = 4
        os = linux
        version = go1.26.5
serf_lan:
        coordinate_resets = 0
        encrypted = true
        event_queue = 0
        event_time = 964
        failed = 0
        health_score = 0
        intent_queue = 0
        left = 0
        member_time = 341450
        members = 14
        query_queue = 0
        query_time = 1
acl {
  enabled = true
  default_policy = "deny"
  enable_token_persistence = true
}
log_json = true
log_level = "info"

connect {
  enabled = true
}

ports {
  grpc = 8502
}

bind_addr = "<node ip>"

addresses {
  grpc     = "127.0.0.1"
  grpc_tls = "<node ip>"
  dns      = "<node ip>"
  http     = "127.0.0.1"
}

node_name  = "<node name>"
datacenter = "<datacenter>"

performance {
  raft_multiplier = 1
}

tls {
  https {
    verify_incoming = false
    verify_outgoing = true
    ca_file = "/secrets/consul/ca.pem"
  }
  internal_rpc {
    verify_incoming = true
    verify_outgoing = true
    ca_file = "/secrets/consul/ca.pem"
    verify_server_hostname = true
  }
}

auto_encrypt {
  tls = true
}

data_dir = "/opt/consul"

ui_config {
  enabled = true
}

server = false

retry_join = [ "<consul servers>" ]

recursors = [ "127.0.0.53" ]

# gossip encryption key and agent ACL token redacted
Server info
agent:
        check_monitors = 0
        check_ttls = 0
        checks = 0
        services = 0
build:
        prerelease =
        revision = a3eb721c
        version = 2.0.4
        version_metadata =
consul:
        acl = enabled
        bootstrap = false
        known_datacenters = 1
        leader = true
        leader_addr = <server ip>:8300
        server = true
raft:
        applied_index = 20819754
        commit_index = 20819754
        fsm_pending = 0
        last_contact = 0
        last_log_index = 20819754
        last_log_term = 125
        last_snapshot_index = 20804286
        last_snapshot_term = 125
        latest_configuration = [{Suffrage:Voter ID:... Address:<server ip>:8300} {Suffrage:Voter ID:... Address:<server ip>:8300} {Suffrage:Voter ID:... Address:<server ip>:8300}]
        latest_configuration_index = 0
        num_peers = 2
        protocol_version = 3
        protocol_version_max = 3
        protocol_version_min = 0
        snapshot_version_max = 1
        snapshot_version_min = 0
        state = Leader
        term = 125
runtime:
        arch = amd64
        cpu_count = 2
        goroutines = 639
        max_procs = 2
        os = linux
        version = go1.26.7
serf_lan:
        coordinate_resets = 0
        encrypted = true
        event_queue = 0
        event_time = 124
        failed = 0
        health_score = 0
        intent_queue = 0
        left = 0
        member_time = 239876
        members = 12
        query_queue = 0
        query_time = 1
serf_wan:
        coordinate_resets = 0
        encrypted = true
        event_queue = 0
        event_time = 1
        failed = 0
        health_score = 0
        intent_queue = 0
        left = 0
        member_time = 13230
        members = 3
        query_queue = 0
        query_time = 1
acl {
  enabled = true
  default_policy = "deny"
  enable_token_persistence = true
}
log_json = true

connect {
  enabled = true
}

ports {
  https = 8501
  grpc = 8502
}

bind_addr = "172.18.1.231"

addresses {
  grpc = "127.0.0.1"
  grpc_tls = "0.0.0.0"
  dns = "0.0.0.0"
  https = "0.0.0.0"
}

node_name = "consul01-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 = [ "172.16.1.231", "172.16.1.232", "172.16.1.233" ]

recursors = [ "127.0.0.53" ]

Operating system and Environment details

Consul 2.0.4 client agents (also seen with 2.0.3 clients), Linux/amd64, running in
Docker. Cluster peering between two datacenters, mesh gateways, ACLs enabled,
auto_encrypt plus TLS on internal RPC. The affected sidecar runs in transparent proxy
mode with zero explicit upstreams, so all of its upstreams are inferred from the
imported peer services.

Log Fragments

One client agent in the importing datacenter, one tproxy sidecar with 59 imported
upstreams across two peers. Counting Failed to handle update from watch events
carrying an upstream-peer: correlation ID:

distinct peered upstreams 59
total error deliveries 5,582
from the tproxy sidecar 5,567
from 5 non-tproxy sidecars 3 each
max deliveries of one watch ID within one second 38

The same logical watch reporting an error 38 times at consecutive microsecond
timestamps is 38 stranded watcher goroutines for that one watch. The non-tproxy
sidecars got exactly one delivery per watch, as expected:

{"@level":"error","@message":"Failed to handle update from watch","@module":"agent.proxycfg",
 "@timestamp":"...342943Z","error":"error filling agent cache: rpc error: code = Unknown desc = subscription closed by server, server is shutting down",
 "id":"upstream-peer:<svc>?peer=<peer>","kind":"connect-proxy","service_id":"<tproxy sidecar>"}
{"@level":"error","@message":"Failed to handle update from watch","@module":"agent.proxycfg",
 "@timestamp":"...342961Z","error":"...","id":"upstream-peer:<svc>?peer=<peer>", ...}
{"@level":"error","@message":"Failed to handle update from watch","@module":"agent.proxycfg",
 "@timestamp":"...342970Z","error":"...","id":"upstream-peer:<svc>?peer=<peer>", ...}
   ... 35 more for the same id, same second ...

Goroutine growth on that agent, from two /debug/pprof/goroutine?debug=1 captures
360s apart:

total: 2504 -> 2616  (+112)

  +115  (1467 -> 1582)
      github.com/hashicorp/consul/agent/submatview.(*materializer).query+0x185
      github.com/hashicorp/consul/agent/submatview.(*RPCMaterializer).Query+0x24
      github.com/hashicorp/consul/agent/submatview.(*Store).NotifyCallback.func1+0x21c

consul.runtime.num_goroutines sampled over the same period — flat, then a jump per
query window, with only ~4 of each batch released:

14:44:53  1449   -3
14:45:24  1564  +115
14:45:54  1570    +6
   ... flat ...
14:50:24  1694  +118
14:50:54  1690    -4

The container is then OOM-killed (Exit Code: 137) against a 512 MiB limit.

For contrast, the control client above — same config, one tproxy sidecar, no imported
peered services — has been up 7 days with zero restarts and a flat goroutine count.

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions