Skip to content

fix(coderd): fix memory leak in watchWorkspaceAgentMetadata #10685

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 5 commits into from
Nov 16, 2023
Merged

fix(coderd): fix memory leak in watchWorkspaceAgentMetadata #10685

Show file tree
Hide file tree
Changes from 4 commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
e6ad02f
fix(coderd): fix memory leak in `watchWorkspaceAgentMetadata`
mafredri Nov 14, 2023
65a9899
fixes
mafredri Nov 15, 2023
ab3cea2
add test that can reproduce memory leak
mafredri Nov 15, 2023
1da56e6
remove unused testutil function
mafredri Nov 16, 2023
5bb2a4b
break out slice set merger into appendUnique
mafredri Nov 16, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
112 changes: 73 additions & 39 deletions coderd/workspaceagents.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1767,10 +1767,10 @@ func (api *API) workspaceAgentUpdateMetadata(ctx context.Context, workspaceAgent

datum := database.UpdateWorkspaceAgentMetadataParams{
WorkspaceAgentID: workspaceAgent.ID,
Key: []string{},
Value: []string{},
Error: []string{},
CollectedAt: []time.Time{},
Key: make([]string, 0, len(req.Metadata)),
Value: make([]string, 0, len(req.Metadata)),
Error: make([]string, 0, len(req.Metadata)),
CollectedAt: make([]time.Time, 0, len(req.Metadata)),
}

for _, md := range req.Metadata {
Expand Down Expand Up @@ -1835,22 +1835,28 @@ func (api *API) workspaceAgentUpdateMetadata(ctx context.Context, workspaceAgent
// @Router /workspaceagents/{workspaceagent}/watch-metadata [get]
// @x-apidocgen {"skip": true}
func (api *API) watchWorkspaceAgentMetadata(rw http.ResponseWriter, r *http.Request) {
var (
ctx = r.Context()
workspaceAgent = httpmw.WorkspaceAgentParam(r)
log = api.Logger.Named("workspace_metadata_watcher").With(
slog.F("workspace_agent_id", workspaceAgent.ID),
)
// Allow us to interrupt watch via cancel.
ctx, cancel := context.WithCancel(r.Context())
defer cancel()
r = r.WithContext(ctx) // Rewire context for SSE cancellation.

workspaceAgent := httpmw.WorkspaceAgentParam(r)
log := api.Logger.Named("workspace_metadata_watcher").With(
slog.F("workspace_agent_id", workspaceAgent.ID),
)

// Send metadata on updates, we must ensure subscription before sending
// initial metadata to guarantee that events in-between are not missed.
update := make(chan workspaceAgentMetadataChannelPayload, 1)
cancelSub, err := api.Pubsub.Subscribe(watchWorkspaceAgentMetadataChannel(workspaceAgent.ID), func(_ context.Context, byt []byte) {
if ctx.Err() != nil {
return
}

var payload workspaceAgentMetadataChannelPayload
err := json.Unmarshal(byt, &payload)
if err != nil {
api.Logger.Error(ctx, "failed to unmarshal pubsub message", slog.Error(err))
log.Error(ctx, "failed to unmarshal pubsub message", slog.Error(err))
return
}

Expand All @@ -1859,17 +1865,16 @@ func (api *API) watchWorkspaceAgentMetadata(rw http.ResponseWriter, r *http.Requ
select {
case prev := <-update:
// This update wasn't consumed yet, merge the keys.
newKeysSet := make(map[string]struct{})
for _, key := range payload.Keys {
newKeysSet[key] = struct{}{}
}
keys := prev.Keys
prevKeysSet := make(map[string]struct{}, len(prev.Keys))
for _, key := range prev.Keys {
if _, ok := newKeysSet[key]; !ok {
keys = append(keys, key)
prevKeysSet[key] = struct{}{}
}
for _, key := range payload.Keys {
if _, ok := prevKeysSet[key]; !ok {
prev.Keys = append(prev.Keys, key)
}
}
payload.Keys = keys
payload.Keys = prev.Keys
Copy link
Member Author

Choose a reason for hiding this comment

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

This is the actual memory leak (logic bug).

default:
}
// This can never block since we pop and merge beforehand.
Expand All @@ -1881,22 +1886,9 @@ func (api *API) watchWorkspaceAgentMetadata(rw http.ResponseWriter, r *http.Requ
}
defer cancelSub()

sseSendEvent, sseSenderClosed, err := httpapi.ServerSentEventSender(rw, r)
if err != nil {
httpapi.Write(ctx, rw, http.StatusInternalServerError, codersdk.Response{
Message: "Internal error setting up server-sent events.",
Detail: err.Error(),
})
return
}
// Prevent handler from returning until the sender is closed.
defer func() {
<-sseSenderClosed
}()

// We always use the original Request context because it contains
// the RBAC actor.
md, err := api.Database.GetWorkspaceAgentMetadata(ctx, database.GetWorkspaceAgentMetadataParams{
initialMD, err := api.Database.GetWorkspaceAgentMetadata(ctx, database.GetWorkspaceAgentMetadataParams{
WorkspaceAgentID: workspaceAgent.ID,
Keys: nil,
})
Expand All @@ -1908,15 +1900,45 @@ func (api *API) watchWorkspaceAgentMetadata(rw http.ResponseWriter, r *http.Requ
return
}

metadataMap := make(map[string]database.WorkspaceAgentMetadatum)
for _, datum := range md {
log.Debug(ctx, "got initial metadata", "num", len(initialMD))

metadataMap := make(map[string]database.WorkspaceAgentMetadatum, len(initialMD))
for _, datum := range initialMD {
metadataMap[datum.Key] = datum
}
//nolint:ineffassign // Release memory.
initialMD = nil
Comment on lines +1899 to +1900
Copy link
Member

Choose a reason for hiding this comment

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

My understanding here is that we only need the initial slice of metadata from the DB once in order to massage it into a map.
Without this, I assume the initial slice would stay around for the duration of the SSE request?


sseSendEvent, sseSenderClosed, err := httpapi.ServerSentEventSender(rw, r)
if err != nil {
httpapi.Write(ctx, rw, http.StatusInternalServerError, codersdk.Response{
Message: "Internal error setting up server-sent events.",
Detail: err.Error(),
})
return
}
// Prevent handler from returning until the sender is closed.
defer func() {
cancel()
<-sseSenderClosed
}()
// Synchronize cancellation from SSE -> context, this lets us simplify the
// cancellation logic.
go func() {
select {
case <-ctx.Done():
case <-sseSenderClosed:
cancel()
}
}()

var lastSend time.Time
sendMetadata := func() {
lastSend = time.Now()
values := maps.Values(metadataMap)

log.Debug(ctx, "sending metadata", "num", len(values))

_ = sseSendEvent(ctx, codersdk.ServerSentEvent{
Type: codersdk.ServerSentEventTypeData,
Data: convertWorkspaceAgentMetadata(values),
Expand All @@ -1935,10 +1957,11 @@ func (api *API) watchWorkspaceAgentMetadata(rw http.ResponseWriter, r *http.Requ
fetchedMetadata := make(chan []database.WorkspaceAgentMetadatum)
go func() {
defer close(fetchedMetadata)
defer cancel()

for {
select {
case <-sseSenderClosed:
case <-ctx.Done():
return
case payload := <-update:
md, err := api.Database.GetWorkspaceAgentMetadata(ctx, database.GetWorkspaceAgentMetadataParams{
Expand All @@ -1948,24 +1971,35 @@ func (api *API) watchWorkspaceAgentMetadata(rw http.ResponseWriter, r *http.Requ
if err != nil {
if !errors.Is(err, context.Canceled) {
log.Error(ctx, "failed to get metadata", slog.Error(err))
_ = sseSendEvent(ctx, codersdk.ServerSentEvent{
Type: codersdk.ServerSentEventTypeError,
Data: codersdk.Response{
Message: "Failed to get metadata.",
Detail: err.Error(),
},
})
}
return
}
select {
case <-sseSenderClosed:
case <-ctx.Done():
return
// We want to block here to avoid constantly pinging the
// database when the metadata isn't being processed.
case fetchedMetadata <- md:
log.Debug(ctx, "fetched metadata update for keys", "keys", payload.Keys, "num", len(md))
}
}
}
}()
defer func() {
<-fetchedMetadata
}()

pendingChanges := true
for {
select {
case <-sseSenderClosed:
case <-ctx.Done():
return
case md, ok := <-fetchedMetadata:
if !ok {
Expand All @@ -1991,7 +2025,7 @@ func (api *API) watchWorkspaceAgentMetadata(rw http.ResponseWriter, r *http.Requ

func convertWorkspaceAgentMetadata(db []database.WorkspaceAgentMetadatum) []codersdk.WorkspaceAgentMetadata {
// An empty array is easier for clients to handle than a null.
result := []codersdk.WorkspaceAgentMetadata{}
result := make([]codersdk.WorkspaceAgentMetadata, 0, len(db))
for _, datum := range db {
result = append(result, codersdk.WorkspaceAgentMetadata{
Result: codersdk.WorkspaceAgentMetadataResult{
Expand Down
159 changes: 159 additions & 0 deletions coderd/workspaceagents_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,7 @@ import (
"github.com/google/uuid"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
"golang.org/x/xerrors"
"tailscale.com/tailcfg"

"cdr.dev/slog"
Expand All @@ -25,7 +26,9 @@ import (
"github.com/coder/coder/v2/coderd/coderdtest"
"github.com/coder/coder/v2/coderd/database"
"github.com/coder/coder/v2/coderd/database/dbfake"
"github.com/coder/coder/v2/coderd/database/dbmem"
"github.com/coder/coder/v2/coderd/database/dbtime"
"github.com/coder/coder/v2/coderd/database/pubsub"
"github.com/coder/coder/v2/codersdk"
"github.com/coder/coder/v2/codersdk/agentsdk"
"github.com/coder/coder/v2/provisioner/echo"
Expand Down Expand Up @@ -1107,6 +1110,162 @@ func TestWorkspaceAgent_Metadata(t *testing.T) {
post("unknown", unknownKeyMetadata)
}

type testWAMErrorStore struct {
database.Store
err atomic.Pointer[error]
}

func (s *testWAMErrorStore) GetWorkspaceAgentMetadata(ctx context.Context, arg database.GetWorkspaceAgentMetadataParams) ([]database.WorkspaceAgentMetadatum, error) {
err := s.err.Load()
if err != nil {
return nil, *err
}
return s.Store.GetWorkspaceAgentMetadata(ctx, arg)
}

func TestWorkspaceAgent_Metadata_CatchMemoryLeak(t *testing.T) {
t.Parallel()

db := &testWAMErrorStore{Store: dbmem.New()}
psub := pubsub.NewInMemory()
logger := slogtest.Make(t, &slogtest.Options{IgnoreErrors: true}).Named("coderd").Leveled(slog.LevelDebug)
client := coderdtest.New(t, &coderdtest.Options{
Database: db,
Pubsub: psub,
IncludeProvisionerDaemon: true,
Logger: &logger,
})
user := coderdtest.CreateFirstUser(t, client)
authToken := uuid.NewString()
ws := dbfake.Workspace(t, db, database.Workspace{
OrganizationID: user.OrganizationID,
OwnerID: user.UserID,
})
dbfake.WorkspaceBuild(t, db, ws, database.WorkspaceBuild{}, &proto.Resource{
Name: "example",
Type: "aws_instance",
Agents: []*proto.Agent{{
Metadata: []*proto.Agent_Metadata{
{
DisplayName: "First Meta",
Key: "foo1",
Script: "echo hi",
Interval: 10,
Timeout: 3,
},
{
DisplayName: "Second Meta",
Key: "foo2",
Script: "echo bye",
Interval: 10,
Timeout: 3,
},
},
Id: uuid.NewString(),
Auth: &proto.Agent_Token{
Token: authToken,
},
}},
})
workspace, err := client.Workspace(context.Background(), ws.ID)
require.NoError(t, err)
for _, res := range workspace.LatestBuild.Resources {
for _, a := range res.Agents {
require.Equal(t, codersdk.WorkspaceAgentLifecycleCreated, a.LifecycleState)
}
}

agentClient := agentsdk.New(client.URL)
agentClient.SetSessionToken(authToken)

ctx, cancel := context.WithCancel(testutil.Context(t, testutil.WaitSuperLong))

manifest, err := agentClient.Manifest(ctx)
require.NoError(t, err)

post := func(ctx context.Context, key, value string) error {
return agentClient.PostMetadata(ctx, agentsdk.PostMetadataRequest{
Metadata: []agentsdk.Metadata{
{
Key: key,
WorkspaceAgentMetadataResult: codersdk.WorkspaceAgentMetadataResult{
CollectedAt: time.Now(),
Value: value,
},
},
},
})
}

workspace, err = client.Workspace(ctx, workspace.ID)
require.NoError(t, err, "get workspace")

// Start the SSE connection.
metadata, errors := client.WatchWorkspaceAgentMetadata(ctx, manifest.AgentID)

// Discard the output, pretending to be a client consuming it.
wantErr := xerrors.New("test error")
metadataDone := testutil.Go(t, func() {
for {
select {
case <-ctx.Done():
return
case _, ok := <-metadata:
if !ok {
return
}
case err := <-errors:
if err != nil && !strings.Contains(err.Error(), wantErr.Error()) {
assert.NoError(t, err, "watch metadata")
}
return
}
}
})

postDone := testutil.Go(t, func() {
for {
// We need to send two separate metadata updates to trigger the
// memory leak. foo2 will cause the number of foo1 to be doubled, etc.
err = post(ctx, "foo1", "hi")
if err != nil {
if !xerrors.Is(err, context.Canceled) {
assert.NoError(t, err, "post metadata foo1")
}
return
}
err = post(ctx, "foo2", "bye")
if err != nil {
if !xerrors.Is(err, context.Canceled) {
assert.NoError(t, err, "post metadata foo1")
}
return
}
}
})

// In a previously faulty implementation, this database error will trigger
// a close of the goroutine that consumes metadata updates for refreshing
// the metadata sent over SSE. As it was, the exit of the consumer was not
// detected as a trigger to close down the connection.
//
// Further, there was a memory leak in the pubsub subscription that cause
// ballooning of memory (almost double in size every received metadata).
//
// This db error should trigger a close of the SSE connection in the fixed
// implementation. The memory leak should not happen in either case, but
// testing it is not straightforward.
db.err.Store(&wantErr)

select {
case <-ctx.Done():
t.Fatal("timeout waiting for SSE to close")
case <-metadataDone:
}
cancel()
<-postDone
}

func TestWorkspaceAgent_Startup(t *testing.T) {
t.Parallel()

Expand Down
Loading