Skip to content

Fix leaking log subscription contexts#2926

Merged
dperny merged 1 commit into
moby:masterfrom
dperny:fix-logs-leak
Jan 28, 2020
Merged

Fix leaking log subscription contexts#2926
dperny merged 1 commit into
moby:masterfrom
dperny:fix-logs-leak

Conversation

@dperny

@dperny dperny commented Jan 21, 2020

Copy link
Copy Markdown
Collaborator

- What I did

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

- How I did it

Very carefully, over the course of six or so hours

- How to test it

Merge it and see if the complaints dry up.

- Description for the changelog

@thaJeztah

Copy link
Copy Markdown
Member

@cpuguy83 @tonistiigi PTAL 🤗

@thaJeztah

Copy link
Copy Markdown
Member

@dperny could you;

  • remove fixes XXX from your commit message? Otherwise the related ticket will be closed prematurely (it will have to be vendor into dockerd first)
  • would it be useful to have your description of Dockerd eats too much RAM moby#39916 (comment) (or at least part of it) in the commit message? Looks like you did quite an analysis; perhaps some of that is useful to preserve in git's history

@codecov

codecov Bot commented Jan 22, 2020

Copy link
Copy Markdown

Codecov Report

Merging #2926 into master will decrease coverage by 0.05%.
The diff coverage is 10%.

@@            Coverage Diff             @@
##           master    #2926      +/-   ##
==========================================
- Coverage   61.76%   61.71%   -0.06%     
==========================================
  Files         142      142              
  Lines       22986    22994       +8     
==========================================
- Hits        14197    14190       -7     
- Misses       7281     7309      +28     
+ Partials     1508     1495      -13

@thaJeztah

Copy link
Copy Markdown
Member

awesome, thanks!

Comment thread agent/agent.go Outdated
subscriptions = map[string]context.CancelFunc{}
// subscriptionDone is a channel that allows us to notify ourselves
// that a lot subscription should be finished.
subscriptionDone = make(chan string, 50)

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.

What's the reasoning for having this buffered? Why 50 and not 1 or 0?

I think no matter what we choose there is potential for goroutines to pile up waiting for the send.

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

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

I've changed the channel to unbuffered. You're right, buffering doesn't help anything.

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]>

@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

@dperny
dperny merged commit 49e3561 into moby:master Jan 28, 2020
thaJeztah added a commit to thaJeztah/docker that referenced this pull request Jan 29, 2020
full diff: moby/swarmkit@ef128ab...49e3561

changes:

- moby/swarmkit#2926 Fix leaking log subscription contexts
    - addresses moby#39916 Dockerd eats too much RAM

Signed-off-by: Sebastiaan van Stijn <[email protected]>
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

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants