Skip to content
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

Jump to bottom

internal: MediaInfo.UploadRequest possible goroutines leaking #1651

Closed
rntk opened this issue Nov 5, 2019 · 3 comments
Closed

internal: MediaInfo.UploadRequest possible goroutines leaking #1651

rntk opened this issue Nov 5, 2019 · 3 comments
Assignees
@frankyn @tritone
Labels
api: storage Issues related to the Cloud Storage API. priority: p2 Moderately-important priority. Fix may not be included in next release. type: bug Error or flaw in code with unintended results or allowing sub-optimal usage patterns.

Comments

@rntk
Copy link

rntk commented Nov 5, 2019

Function UploadRequest (https://github.com/googleapis/google-api-go-client/blob/v0.13.0/internal/gensupport/media.go#L273) return function GetBody.

GetBody, by combineBodyMedia, call function newMultipartReader (https://github.com/googleapis/google-api-go-client/blob/v0.13.0/internal/gensupport/media.go#L120).

newMultipartReader use io.Pipe to create new io.Reader and create new goroutine to provide data for pipe (https://github.com/googleapis/google-api-go-client/blob/v0.13.0/internal/gensupport/media.go#L131).

From https://golang.org/pkg/io/#Pipe

each Write to the PipeWriter blocks until it has satisfied one or more Reads from the PipeReader that fully consume the written data.

If we call GetBody and do not consume data from Reader we got "forever" blocked goroutine on (https://github.com/googleapis/google-api-go-client/blob/v0.13.0/internal/gensupport/media.go#L131).

In particular, this lead to goroutines and memory leaking in storage client. In one of long running processes (about 7 days) got leaked: 62 goroutines and 496Mb of memory.

Example of debug stack trace:

2019/11/04 10:41:32 Start getBody
goroutine 2441 [running]:
runtime/debug.Stack(0x50c09c, 0xc0000ae000, 0x2)
	/opt/go/src/runtime/debug/stack.go:24 +0x9d
runtime/debug.PrintStack()
	/opt/go/src/runtime/debug/stack.go:16 +0x22
google.golang.org/api/internal/gensupport.(*MediaInfo).UploadRequest.func2(0xa4b760, 0xc0003da300, 0xf0ef40, 0x7fe2a9795000)
	/home/dev/go/pkg/mod/google.golang.org/api@v0.11.0/internal/gensupport/media.go:298 +0xbc
net/http.(*Transport).roundTrip(0xee7d80, 0xc0003da200, 0x964d80, 0xee7b01, 0xc00011f4a0)
	/opt/go/src/net/http/transport.go:556 +0x760
net/http.(*Transport).RoundTrip(0xee7d80, 0xc0003da200, 0xa5f8f9, 0xa, 0xc00011f528)
	/opt/go/src/net/http/roundtrip.go:17 +0x35
google.golang.org/api/transport/http.parameterTransport.RoundTrip(0xa6b827, 0x1e, 0x0, 0x0, 0x0, 0x0, 0xb1fca0, 0xee7d80, 0xc0003da100, 0xa67ced, ...)
	/home/dev/go/pkg/mod/google.golang.org/api@v0.11.0/transport/http/dial.go:151 +0x329
go.opencensus.io/plugin/ochttp.(*traceTransport).RoundTrip(0xc000d0e580, 0xc0003da100, 0xc00000e360, 0x1, 0x1)
	/home/dev/go/pkg/mod/go.opencensus.io@v0.22.0/plugin/ochttp/trace.go:84 +0x456
go.opencensus.io/plugin/ochttp.statsTransport.RoundTrip(0xb1f340, 0xc000d0e580, 0xc000279f00, 0xc001330e40, 0xc001330e40, 0x9d3be0)
	/home/dev/go/pkg/mod/go.opencensus.io@v0.22.0/plugin/ochttp/client_stats.go:57 +0x5cc
go.opencensus.io/plugin/ochttp.(*Transport).RoundTrip(0xc0001241e0, 0xc000279f00, 0xc000279f00, 0x0, 0x150)
	/home/dev/go/pkg/mod/go.opencensus.io@v0.22.0/plugin/ochttp/client.go:99 +0x20e
golang.org/x/oauth2.(*Transport).RoundTrip(0xc0000eaab0, 0xc000279e00, 0x0, 0x0, 0x0)
	/home/dev/go/pkg/mod/golang.org/x/oauth2@v0.0.0-20190604053449-0f29369cfe45/transport.go:56 +0x124
net/http.send(0xc000279e00, 0xb1f3e0, 0xc0000eaab0, 0x0, 0x0, 0x0, 0xc0000104e0, 0xc001323ae0, 0x1, 0x0)
	/opt/go/src/net/http/client.go:250 +0x43a
net/http.(*Client).send(0xc0000eaae0, 0xc000279e00, 0x0, 0x0, 0x0, 0xc0000104e0, 0x0, 0x1, 0xc000129848)
	/opt/go/src/net/http/client.go:174 +0xfa
net/http.(*Client).do(0xc0000eaae0, 0xc000279e00, 0x0, 0x0, 0x0)
	/opt/go/src/net/http/client.go:641 +0x3ce
net/http.(*Client).Do(...)
	/opt/go/src/net/http/client.go:509
google.golang.org/api/internal/gensupport.send(0xb2ad20, 0xc00009e020, 0xc0000eaae0, 0xc000279d00, 0xf103a0, 0x0, 0xc0001299a8)
	/home/dev/go/pkg/mod/google.golang.org/api@v0.11.0/internal/gensupport/send.go:72 +0x106
google.golang.org/api/internal/gensupport.SendRequest(0xb2ad20, 0xc00009e020, 0xc0000eaae0, 0xc000279d00, 0xc000129c98, 0x79, 0x7fe2a97da198)
	/home/dev/go/pkg/mod/google.golang.org/api@v0.11.0/internal/gensupport/send.go:57 +0x19c
google.golang.org/api/storage/v1.(*ObjectsInsertCall).doRequest(0xc000125a40, 0xa5b0d9, 0x4, 0x0, 0x0, 0x0)
	/home/dev/go/pkg/mod/google.golang.org/api@v0.11.0/storage/v1/storage-gen.go:10041 +0x8d1
google.golang.org/api/storage/v1.(*ObjectsInsertCall).Do(0xc000125a40, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
	/home/dev/go/pkg/mod/google.golang.org/api@v0.11.0/storage/v1/storage-gen.go:10053 +0xa8
cloud.google.com/go/storage.(*Writer).open.func1(0xc0000bcfc0, 0xc000220540, 0xc0000104b0, 0xc001330ce0, 0x1, 0x1)
	/home/dev/go/pkg/mod/cloud.google.com/go/storage@v1.1.2/writer.go:160 +0x77a
created by cloud.google.com/go/storage.(*Writer).open
	/home/dev/go/pkg/mod/cloud.google.com/go/storage@v1.1.2/writer.go:110 +0x3f3

2019/11/04 10:41:33 Start getBody
goroutine 2441 [running]:
runtime/debug.Stack(0x50c09c, 0xc0000ae000, 0x2)
	/opt/go/src/runtime/debug/stack.go:24 +0x9d
runtime/debug.PrintStack()
	/opt/go/src/runtime/debug/stack.go:16 +0x22
google.golang.org/api/internal/gensupport.(*MediaInfo).UploadRequest.func2(0xa4b760, 0xc0003da400, 0xf0ef40, 0x7fe2a9795000)
	/home/dev/go/pkg/mod/google.golang.org/api@v0.11.0/internal/gensupport/media.go:298 +0xbc
net/http.(*Transport).roundTrip(0xee7d80, 0xc0003da200, 0x964d80, 0xee7b01, 0xc00011f4a0)
	/opt/go/src/net/http/transport.go:556 +0x760
net/http.(*Transport).RoundTrip(0xee7d80, 0xc0003da200, 0xa5f8f9, 0xa, 0xc00011f528)
	/opt/go/src/net/http/roundtrip.go:17 +0x35
google.golang.org/api/transport/http.parameterTransport.RoundTrip(0xa6b827, 0x1e, 0x0, 0x0, 0x0, 0x0, 0xb1fca0, 0xee7d80, 0xc0003da100, 0xa67ced, ...)
	/home/dev/go/pkg/mod/google.golang.org/api@v0.11.0/transport/http/dial.go:151 +0x329
go.opencensus.io/plugin/ochttp.(*traceTransport).RoundTrip(0xc000d0e580, 0xc0003da100, 0xc00000e360, 0x1, 0x1)
	/home/dev/go/pkg/mod/go.opencensus.io@v0.22.0/plugin/ochttp/trace.go:84 +0x456
go.opencensus.io/plugin/ochttp.statsTransport.RoundTrip(0xb1f340, 0xc000d0e580, 0xc000279f00, 0xc001330e40, 0xc001330e40, 0x9d3be0)
	/home/dev/go/pkg/mod/go.opencensus.io@v0.22.0/plugin/ochttp/client_stats.go:57 +0x5cc
go.opencensus.io/plugin/ochttp.(*Transport).RoundTrip(0xc0001241e0, 0xc000279f00, 0xc000279f00, 0x0, 0x150)
	/home/dev/go/pkg/mod/go.opencensus.io@v0.22.0/plugin/ochttp/client.go:99 +0x20e
golang.org/x/oauth2.(*Transport).RoundTrip(0xc0000eaab0, 0xc000279e00, 0x0, 0x0, 0x0)
	/home/dev/go/pkg/mod/golang.org/x/oauth2@v0.0.0-20190604053449-0f29369cfe45/transport.go:56 +0x124
net/http.send(0xc000279e00, 0xb1f3e0, 0xc0000eaab0, 0x0, 0x0, 0x0, 0xc0000104e0, 0xc001323ae0, 0x1, 0x0)
	/opt/go/src/net/http/client.go:250 +0x43a
net/http.(*Client).send(0xc0000eaae0, 0xc000279e00, 0x0, 0x0, 0x0, 0xc0000104e0, 0x0, 0x1, 0xc000129848)
	/opt/go/src/net/http/client.go:174 +0xfa
net/http.(*Client).do(0xc0000eaae0, 0xc000279e00, 0x0, 0x0, 0x0)
	/opt/go/src/net/http/client.go:641 +0x3ce
net/http.(*Client).Do(...)
	/opt/go/src/net/http/client.go:509
google.golang.org/api/internal/gensupport.send(0xb2ad20, 0xc00009e020, 0xc0000eaae0, 0xc000279d00, 0xf103a0, 0x0, 0xc0001299a8)
	/home/dev/go/pkg/mod/google.golang.org/api@v0.11.0/internal/gensupport/send.go:72 +0x106
google.golang.org/api/internal/gensupport.SendRequest(0xb2ad20, 0xc00009e020, 0xc0000eaae0, 0xc000279d00, 0xc000129c98, 0x79, 0x7fe2a97da198)
	/home/dev/go/pkg/mod/google.golang.org/api@v0.11.0/internal/gensupport/send.go:57 +0x19c
google.golang.org/api/storage/v1.(*ObjectsInsertCall).doRequest(0xc000125a40, 0xa5b0d9, 0x4, 0x0, 0x0, 0x0)
	/home/dev/go/pkg/mod/google.golang.org/api@v0.11.0/storage/v1/storage-gen.go:10041 +0x8d1
google.golang.org/api/storage/v1.(*ObjectsInsertCall).Do(0xc000125a40, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
	/home/dev/go/pkg/mod/google.golang.org/api@v0.11.0/storage/v1/storage-gen.go:10053 +0xa8
cloud.google.com/go/storage.(*Writer).open.func1(0xc0000bcfc0, 0xc000220540, 0xc0000104b0, 0xc001330ce0, 0x1, 0x1)
	/home/dev/go/pkg/mod/cloud.google.com/go/storage@v1.1.2/writer.go:160 +0x77a
created by cloud.google.com/go/storage.(*Writer).open
	/home/dev/go/pkg/mod/cloud.google.com/go/storage@v1.1.2/writer.go:110 +0x3f3

go version go1.13 linux/amd64

google storage client v1.1.2
@kevinconaway
Copy link

I've been trying to debug this as well. As far as I can tell, it only seems to occur when the initial request fails and thus GetBody() is called. It appears that when GetBody() is called, the returned body is not closed and thus the pipe stays active. From my internal testing the most common reason for the initial request to fail is http2ErrNoCachedConn.

This has been reported here as well #1380.

The following script reproduces it for me:

package main

import (
	"bytes"
	"context"
	"fmt"
	"io"
	"os"
	"runtime/pprof"
	"sync"
	"time"

	"cloud.google.com/go/storage"
)

func main() {
	storageClient, err := storage.NewClient(context.Background())
	if err != nil {
		fmt.Printf("error getting gcs: %+v\n", err)
		return
	}

        bucketName := "..."
	bucket := storageClient.Bucket(bucketName)

	var wg sync.WaitGroup
	for i := 0; i < 200; i++ {
		wg.Add(1)

		go func(i int) {
			defer wg.Done()

			key := fmt.Sprintf("testing2/part-%d", i)
			contents := []byte(fmt.Sprintf("{\"data\": %d}", i))
			reader := bytes.NewReader(contents)

			wc := bucket.Object(key).NewWriter(context.Background())

			if _, err := io.Copy(wc, reader); err != nil {
				fmt.Printf("error uploading %d: %+v\n", i, err)
				return
			}

			if err := wc.Close(); err != nil {
				fmt.Printf("error closing %d: %+v\n", i, err)
				return
			}
		}(i)
	}

	wg.Wait()

	fmt.Printf("finished, sleeping for a few")

	time.Sleep(10 * time.Second)

	if err := pprof.Lookup("goroutine").WriteTo(os.Stdout, 2); err != nil {
		fmt.Printf("error dumping goroutines\n")
	}
}

After running, you should see one or more goroutines stuck at:

goroutine 2213 [select]:
io.(*pipe).Write(0xc0674c5130, 0xc065713220, 0x62, 0xa0, 0x0, 0x0, 0x0)
	/go1.13.1.linux.amd64/src/io/pipe.go:87 +0x1fb
io.(*PipeWriter).Write(0xc000312c38, 0xc065713220, 0x62, 0xa0, 0x954160, 0x9e8120, 0x4d7701)
	/go1.13.1.linux.amd64/src/io/pipe.go:153 +0x4c
bytes.(*Buffer).WriteTo(0xc067a0c990, 0xab3b80, 0xc000312c38, 0x7f567c127008, 0xc067a0c990, 0x101)
	/go1.13.1.linux.amd64/src/bytes/buffer.go:239 +0xb5
io.copyBuffer(0xab3b80, 0xc000312c38, 0xab3260, 0xc067a0c990, 0x0, 0x0, 0x0, 0x2, 0x0, 0x0)
	/go1.13.1.linux.amd64/src/io/io.go:384 +0x33f
io.Copy(...)
	/go1.13.1.linux.amd64/src/io/io.go:364
mime/multipart.(*Writer).CreatePart(0xc067a0c900, 0xc067a0c960, 0xc067a0c960, 0x620835, 0xc066ebf180, 0x0)
	/go1.13.1.linux.amd64/src/mime/multipart/writer.go:121 +0x3fa
vendor/google.golang.org/api/gensupport.newMultipartReader.func1(0xc067a0c8d0, 0xc067156e80, 0x2, 0x2, 0xc067a0c900, 0xc000312c38)
	/vendor/google.golang.org/api/gensupport/media.go:140 +0xc1
created by vendor/google.golang.org/api/gensupport.newMultipartReader
	/vendor/google.golang.org/api/gensupport/media.go:136 +0x346

@jba is this something that you would be able to take a look at? I believe that you added the initial code for GetBody

@jeanbza jeanbza transferred this issue from googleapis/google-api-go-client Nov 5, 2019
@jeanbza jeanbza added api: storage Issues related to the Cloud Storage API. triage me I really want to be triaged. labels Nov 5, 2019
@frankyn frankyn added priority: p2 Moderately-important priority. Fix may not be included in next release. type: bug Error or flaw in code with unintended results or allowing sub-optimal usage patterns. and removed triage me I really want to be triaged. labels Nov 8, 2019
@frankyn
Copy link
Member

frankyn commented Nov 8, 2019 •
edited by tritone
Loading

Hi @rntk and @kevinconaway,

Thanks for filing this issue, as you mentioned we saw the issue in #1380 .

As we understand it now, it's an issue with how io.Pipe is used in the request body. This is being discussed in golang/go#29246.

I'm closing it here. Thank you for your patience.

@frankyn frankyn closed this as completed Nov 8, 2019
@kevinconaway
Copy link

@frankyn Would you reconsider? Based on my investigation, it looks like its not necessarily that io.Pipe is the problem its that the body isn't always being closed when GetBody is used which leaves the pipe reader dangling.

Its possible there is an issue with the implementation in GetBody that could be looked at here.

This was referenced Nov 18, 2019
Closed
Merged
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@frankyn frankyn

@tritone tritone

Labels
api: storage Issues related to the Cloud Storage API. priority: p2 Moderately-important priority. Fix may not be included in next release. type: bug Error or flaw in code with unintended results or allowing sub-optimal usage patterns.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@frankyn @jeanbza @tritone @rntk @kevinconaway