Skip to content

[19.03 backport] Fix leaking subscription contexts#2927

Merged
dperny merged 1 commit into
moby:bump_v19.03from
thaJeztah:19.03_backport_fix_logs_leak
Jan 29, 2020
Merged

[19.03 backport] Fix leaking subscription contexts#2927
dperny merged 1 commit into
moby:bump_v19.03from
thaJeztah:19.03_backport_fix_logs_leak

Conversation

@thaJeztah

Copy link
Copy Markdown
Member

backport of #2926

Fixes leaking subscription contexts, and slightly alters the close
procedure for PublishLogs streams. This in turn prevents leaking whole
connections, and (hopefully) might be a solution for moby/moby#39916

(All line numbers are in terms of the commit immediately proceeding this
one.)

From what I can gather, there exists some possibility for a leak if we
try to close a gRPC stream without reading any final messages.

The documentation for (*grpc.ClientConn).NewStream says:

To ensure resources are not leaked due to the stream returned, one of
the following actions must be performed:

  1. Call Close on the ClientConn
  2. Cancel the context provided
  3. Call RecvMsg until a non-nil error is returned. A
    protobuf-generated client-streaming RPC, for instance, might use
    the helper function CloseAndRecv (note that CloseSend does not
    Recv, therefore is not guaranteed to release all resources).
  4. Receive a non-nil, non-EOF error from Header or SendMsg.

If none of the above happen, a goroutine and a context will be leaked,
grpc will not call the optionally-configured stats handler with a
stat.End message.

In the agent package, we have a function which is supposed to close the
gRPC stream that sends logs to the the manager, agent/agent.go L545-553.
It is called when the worker attempt to send logs after the context has
been canceled, or when the agent explicitly cancels the log stream. It
does not call Recv, which is one possible route for a leak.

This means, additionally, that the context is not being canceled. This
context is created in the agent's main run loop, agent/agent.go
L298-314. A new sub-context is created for each Subscribe call, and this
context should be canceled whenever the subscription is closed. The
subscription is closed only upon receiving a message from the manager.

The logs code is complex, and the manager code is located in
./manager/logbroker. The agent connects to the manager and initiates a
server stream, through which the manager sends new log subscriptions
(the ListenSubscriptions stream). When a user requests logs, the manager
creates a new stream down to the user (the SubscribeLogs stream) and
sends a message on the ListenSubscriptions stream of all agents with the
desired logs. The agent then creates a third stream (the PublishLogs
stream) through which it sends logs to the manager. The stream that is
being leaked is this third stream, PublishLogs. These three streams all
exist in separate, concurrent goroutines, and communicate over a complex
series of channels.

The problem, basically, is this:

  • The ListenSubscriptions stream starts a watch on a queue. It knows a
    subscription is relevant to the agent if the subscription contains the
    NodeID of the agent.
  • When a subscription is finished, it is updated to say that it is
    closed, and then published to this queue to notify all agents.
  • When the manager receives a message on the PublishLogs stream that
    indicates the agent has no more logs to send, it removes the node ID
    from the subscription.
  • Therefore, if the PublishLogs call finishes before the Subscription is
    closed, the Close message is never sent to the agent. This is
    generally intended behavior, as the Close message is not supposed to
    clean up dangling streams, it is supposed to notify that a logs
    request in progress should be stopped.

Additionally, the manager may never get the opportunity to send the
Close message, if, for example, it crashes. This means it is the agent's
responsibility to clean up any completed logs streams. Further, to
guarantee that we don't leak resources, we add a Recv call to the
function that closes the PublishLogs stream.

Fixes leaking subscription contexts, and slightly alters the close
procedure for PublishLogs streams. This in turn prevents leaking whole
connections, and (hopefully) might be a solution for moby/moby#39916

(All line numbers are in terms of the commit immediately proceeding this
one.)

From what I can gather, there exists some possibility for a leak if we
try to close a gRPC stream without reading any final messages.

The documentation for (*grpc.ClientConn).NewStream says:

> To ensure resources are not leaked due to the stream returned, one of
> the following actions must be performed:
>
>   1. Call Close on the ClientConn
>   2. Cancel the context provided
>   3. Call RecvMsg until a non-nil error is returned. A
>      protobuf-generated client-streaming RPC, for instance, might use
>      the helper function CloseAndRecv (note that CloseSend does not
>      Recv, therefore is not guaranteed to release all resources).
>   4. Receive a non-nil, non-EOF error from Header or SendMsg.
>
> If none of the above happen, a goroutine and a context will be leaked,
> grpc will not call the optionally-configured stats handler with a
> stat.End message.

In the agent package, we have a function which is supposed to close the
gRPC stream that sends logs to the the manager, agent/agent.go L545-553.
It is called when the worker attempt to send logs after the context has
been canceled, or when the agent explicitly cancels the log stream. It
does not call Recv, which is one possible route for a leak.

This means, additionally, that the context is not being canceled. This
context is created in the agent's main run loop, agent/agent.go
L298-314. A new sub-context is created for each Subscribe call, and this
context should be canceled whenever the subscription is closed. The
subscription is closed only upon receiving a message from the manager.

The logs code is complex, and the manager code is located in
./manager/logbroker. The agent connects to the manager and initiates a
server stream, through which the manager sends new log subscriptions
(the ListenSubscriptions stream). When a user requests logs, the manager
creates a new stream down to the user (the SubscribeLogs stream) and
sends a message on the ListenSubscriptions stream of all agents with the
desired logs. The agent then creates a third stream (the PublishLogs
stream) through which it sends logs to the manager. The stream that is
being leaked is this third stream, PublishLogs. These three streams all
exist in separate, concurrent goroutines, and communicate over a complex
series of channels.

The problem, basically, is this:

* The ListenSubscriptions stream starts a watch on a queue. It knows a
  subscription is relevant to the agent if the subscription contains the
  NodeID of the agent.
* When a subscription is finished, it is updated to say that it is
  closed, and then published to this queue to notify all agents.
* When the manager receives a message on the PublishLogs stream that
  indicates the agent has no more logs to send, it removes the node ID
  from the subscription.
* Therefore, if the PublishLogs call finishes before the Subscription is
  closed, the Close message is never sent to the agent. This is
  generally intended behavior, as the Close message is not supposed to
  clean up dangling streams, it is supposed to notify that a logs
  request in progress should be stopped.

Additionally, the manager may never get the opportunity to send the
Close message, if, for example, it crashes. This means it is the agent's
responsibility to clean up any completed logs streams. Further, to
guarantee that we don't leak resources, we add a Recv call to the
function that closes the PublishLogs stream.

Signed-off-by: Drew Erny <[email protected]>
(cherry picked from commit d12f9f6)
Signed-off-by: Sebastiaan van Stijn <[email protected]>
@thaJeztah

Copy link
Copy Markdown
Member Author

@dperny @cpuguy83 ptal

@cpuguy83 cpuguy83 left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@codecov

codecov Bot commented Jan 28, 2020

Copy link
Copy Markdown

Codecov Report

Merging #2927 into bump_v19.03 will decrease coverage by 0.13%.
The diff coverage is 10%.

@@               Coverage Diff               @@
##           bump_v19.03    #2927      +/-   ##
===============================================
- Coverage        62.19%   62.05%   -0.14%     
===============================================
  Files              139      139              
  Lines            22317    22325       +8     
===============================================
- Hits             13880    13854      -26     
- Misses            6967     6998      +31     
- Partials          1470     1473       +3

@dperny
dperny merged commit 062b694 into moby:bump_v19.03 Jan 29, 2020
thaJeztah added a commit to thaJeztah/docker that referenced this pull request Jan 29, 2020
full diff: moby/swarmkit@f35d910...062b694

changes:

- moby/swarmkit#2927 [19.03 backport] Fix leaking subscription contexts
    - backport of moby/swarmkit#2926 Fix leaking log subscription contexts
    - addresses moby#39916 Dockerd eats too much RAM

Signed-off-by: Sebastiaan van Stijn <[email protected]>
tiborvass pushed a commit to tiborvass/docker that referenced this pull request Feb 4, 2020
full diff: moby/swarmkit@f35d910...062b694

changes:

- moby/swarmkit#2927 [19.03 backport] Fix leaking subscription contexts
    - backport of moby/swarmkit#2926 Fix leaking log subscription contexts
    - addresses moby#39916 Dockerd eats too much RAM

Signed-off-by: Sebastiaan van Stijn <[email protected]>
docker-jenkins pushed a commit to docker-archive/docker-ce that referenced this pull request Feb 4, 2020
full diff: moby/swarmkit@f35d910...062b694

changes:

- moby/swarmkit#2927 [19.03 backport] Fix leaking subscription contexts
    - backport of moby/swarmkit#2926 Fix leaking log subscription contexts
    - addresses moby/moby#39916 Dockerd eats too much RAM

Signed-off-by: Sebastiaan van Stijn <[email protected]>
Upstream-commit: 0dd0af939f98500daf86f96f3fbd039af397dd8a
Component: engine
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants