Google-cloud-go: internal: MediaInfo.UploadRequest possible goroutines leaking

Created on 5 Nov 2019  路  3Comments  路  Source: googleapis/google-cloud-go

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/[email protected]/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/[email protected]/transport/http/dial.go:151 +0x329
go.opencensus.io/plugin/ochttp.(*traceTransport).RoundTrip(0xc000d0e580, 0xc0003da100, 0xc00000e360, 0x1, 0x1)
    /home/dev/go/pkg/mod/[email protected]/plugin/ochttp/trace.go:84 +0x456
go.opencensus.io/plugin/ochttp.statsTransport.RoundTrip(0xb1f340, 0xc000d0e580, 0xc000279f00, 0xc001330e40, 0xc001330e40, 0x9d3be0)
    /home/dev/go/pkg/mod/[email protected]/plugin/ochttp/client_stats.go:57 +0x5cc
go.opencensus.io/plugin/ochttp.(*Transport).RoundTrip(0xc0001241e0, 0xc000279f00, 0xc000279f00, 0x0, 0x150)
    /home/dev/go/pkg/mod/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/writer.go:160 +0x77a
created by cloud.google.com/go/storage.(*Writer).open
    /home/dev/go/pkg/mod/cloud.google.com/go/[email protected]/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/[email protected]/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/[email protected]/transport/http/dial.go:151 +0x329
go.opencensus.io/plugin/ochttp.(*traceTransport).RoundTrip(0xc000d0e580, 0xc0003da100, 0xc00000e360, 0x1, 0x1)
    /home/dev/go/pkg/mod/[email protected]/plugin/ochttp/trace.go:84 +0x456
go.opencensus.io/plugin/ochttp.statsTransport.RoundTrip(0xb1f340, 0xc000d0e580, 0xc000279f00, 0xc001330e40, 0xc001330e40, 0x9d3be0)
    /home/dev/go/pkg/mod/[email protected]/plugin/ochttp/client_stats.go:57 +0x5cc
go.opencensus.io/plugin/ochttp.(*Transport).RoundTrip(0xc0001241e0, 0xc000279f00, 0xc000279f00, 0x0, 0x150)
    /home/dev/go/pkg/mod/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/writer.go:160 +0x77a
created by cloud.google.com/go/storage.(*Writer).open
    /home/dev/go/pkg/mod/cloud.google.com/go/[email protected]/writer.go:110 +0x3f3

go version go1.13 linux/amd64

google storage client v1.1.2

storage p2 bug
Source
picture rntk

Most helpful comment

@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.

picture kevinconaway on 11 Nov 2019
👍2

All 3 comments

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 https://github.com/googleapis/google-cloud-go/issues/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

kevinconaway picture kevinconaway on 5 Nov 2019

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 https://github.com/golang/go/issues/29246.

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

frankyn picture frankyn on 8 Nov 2019

@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.

kevinconaway picture kevinconaway on 11 Nov 2019
👍2
Was this page helpful?
0 / 5 - 0 ratings

Related issues

twoism picture twoism  路  4Comments
nfisher picture nfisher  路  3Comments
MoreThanCarbon picture MoreThanCarbon  路  3Comments
lukaszraczylo picture lukaszraczylo  路  3Comments
muratsplat picture muratsplat  路  3Comments