search

golang / go

The Go programming language
https://go.dev
BSD 3-Clause "New" or "Revised" License
124.4k stars 17.71k forks source link

x/net/http2: stream was reset: PROTOCOL_ERROR #31534

Open sinhaashish opened 5 years ago

sinhaashish commented 5 years ago

What version of Go are you using (go version)?

$ go version
go version go1.12 linux/amd64

Does this issue reproduce with the latest release?

What operating system and processor architecture are you using (go env)?

go env Output
$ go env

```
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/ashish/.cache/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/ashish/code/go"
GOPROXY=""
GORACE=""
GOROOT="/home/ashish/.gimme/versions/go1.12.linux.amd64"
GOTMPDIR=""
GOTOOLDIR="/home/ashish/.gimme/versions/go1.12.linux.amd64/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/home/ashish/code/go/src/github.com/minio/minio-java/go.mod"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build786486078=/tmp/go-build -gno-record-gcc-switches"
```

What did you do?

I am using minio for Object storage. Minio is a golang project using go1.12 as the base go version. The server is HTTP2 enabled. I use using minio java client which uses okhttp3 . when i try to store the object in a bucket in multi threaded mode i get okhttp3.internal.http2.StreamResetException: stream was reset: NO_ERROR. Refer https://github.com/minio/minio/issues/7501 .

okhttp3.OkHttpClient uses http2.0 by default which causes such issue. If i forcefuly set the protocol to 1.1 ,it works fine. Refer PR https://github.com/minio/minio-java/pull/766.

I find there is some issue with Go1.12 or okhttp3 as i found this issue in the community. Refer https://github.com/square/okhttp/issues/3955 The only solution provided there was to revert to HTTP1_1 .

Setting the protocol to 1.1 is not the solution as i am not using the functionality of HTTP2.0 enabled server.

Raised the issue with okhhttp refer https://github.com/square/okhttp/issues/4964 Below is the code which replicates the problem 

 import io.minio.MinioClient;
class PutObjectRunnable implements Runnable {
    MinioClient client;
    String bucketName;
    String filename;

    public PutObjectRunnable(MinioClient client, String bucketName, String filename) {
        this.client = client;
        this.bucketName = bucketName;
        this.filename = filename;
    }

    public void run() {
        StringBuffer traceBuffer = new StringBuffer();

        try {

            client.putObject(bucketName, filename, filename);

        } catch (Exception e) {
            System.err.print(traceBuffer.toString());
            e.printStackTrace();
        }
    }
}


public class ThreadedPutObject {
    public static void main(String args[]) throws Exception {
    try{
        MinioClient client = new MinioClient("https://play.min.io:9000", "Q3AM3UQ867SPQQA43P2F", "zuf+tfteSlswRu7BJ86wekitnifILbZam1KYY3TG", true);
        client.traceOn(System.out);
        long startTime = System.currentTimeMillis();
         boolean found = minioClient.bucketExists("my-bucketname");
      if (found) {
        System.out.println("my-bucketname already exists");
      } else {
        // Create bucket 'my-bucketname'.
        minioClient.makeBucket("my-bucketname");
        System.out.println("my-bucketname is created successfully");
      }        
      Thread[] threads = new Thread[7];
      String[] location = new String[]{"<<PATH_TO_OBJECT_1>>",
                                       "<<PATH_TO_OBJECT_2>>",
                                       "<<PATH_TO_OBJECT_3>>",
                                       "<<PATH_TO_OBJECT_4>>",
                                       "<<PATH_TO_OBJECT_5>>",
                                       "<<PATH_TO_OBJECT_6>>",  
                                       "<<PATH_TO_OBJECT_7>>" };

      for (int i = 0; i < 7; i++) {
            PutObjectRunnable pr = new PutObjectRunnable(client, "my-bucketname",location[i] );
          threads[i] = new Thread(pr);
      }
      for (int i = 0; i < 7; i++) {
        threads[i].start();
      }
            // Waiting for threads to complete.
      for (int i = 0; i < 7; i++) {
         threads[i].join();
          System.out.println(i);
        }
        // All threads are completed.
        } catch (Exception e) {
            throw e;
        }
        System.out.println("uploaded");
    }
}

What did you expect to see?

Object should have been uploaded.

What did you see instead?

okhttp3.internal.http2.StreamResetException: stream was reset: PROTOCOL_ERROR

agnivade commented 5 years ago

Can you run the Minio server with GODEBUG=http2debug=2 and paste the logs ?

sinhaashish commented 5 years ago

GODEBUG=http2debug=2

Log :

2019/04/19 21:23:54 http2: decoded hpack field header field "x-amz-date" = "20190419T155331Z"
2019/04/19 21:23:54 http2: decoded hpack field header field "authorization" = "AWS4-HMAC-SHA256 Credential=minio/20190419/us-east-1/s3/aws4_request, SignedHeaders=content-md5;host;x-amz-content-sha256;x-amz-date, Signature=b335653e30400fb6db22eb75e23fde1378f05eef08218bee66bcce558a9b4fc2"
2019/04/19 21:23:54 http2: decoded hpack field header field "content-type" = "application/octet-stream"
2019/04/19 21:23:54 http2: decoded hpack field header field "content-length" = "308"
2019/04/19 21:23:54 http2: decoded hpack field header field "accept-encoding" = "gzip"
2019/04/19 21:23:54 http2: Framer 0xc00050e620: wrote RST_STREAM stream=36965 len=4 ErrCode=PROTOCOL_ERROR
2019/04/19 21:23:54 http2: server read frame HEADERS flags=END_HEADERS stream=36967 len=39
2019/04/19 21:23:54 http2: Framer 0xc00050e620: read HEADERS flags=END_HEADERS stream=36969 len=39
2019/04/19 21:23:54 http2: decoded hpack field header field ":method" = "PUT"
2019/04/19 21:23:54 http2: decoded hpack field header field ":path" = "/sinha/home/ashish/Sample/empty"
2019/04/19 21:23:54 http2: decoded hpack field header field ":authority" = "localhost:9000"
2019/04/19 21:23:54 http2: decoded hpack field header field ":scheme" = "https"
2019/04/19 21:23:54 http2: decoded hpack field header field "content-md5" = "0ObLjpgreGc9ZUcDuWdW3g=="
2019/04/19 21:23:54 http2: decoded hpack field header field "user-agent" = "MinIO (amd64; amd64) minio-java/dev"
2019/04/19 21:23:54 http2: decoded hpack field header field "x-amz-content-sha256" = "UNSIGNED-PAYLOAD"
2019/04/19 21:23:54 http2: decoded hpack field header field "x-amz-date" = "20190419T155331Z"
2019/04/19 21:23:54 http2: decoded hpack field header field "authorization" = "AWS4-HMAC-SHA256 Credential=minio/20190419/us-east-1/s3/aws4_request, SignedHeaders=content-md5;host;x-amz-content-sha256;x-amz-date, Signature=b335653e30400fb6db22eb75e23fde1378f05eef08218bee66bcce558a9b4fc2"
2019/04/19 21:23:54 http2: decoded hpack field header field "content-type" = "application/octet-stream"
2019/04/19 21:23:54 http2: decoded hpack field header field "content-length" = "308"
2019/04/19 21:23:54 http2: decoded hpack field header field "accept-encoding" = "gzip"
2019/04/19 21:23:54 http2: Framer 0xc00050e620: wrote RST_STREAM stream=36967 len=4 ErrCode=PROTOCOL_ERROR
2019/04/19 21:23:54 http2: server read frame HEADERS flags=END_HEADERS stream=36969 len=39
2019/04/19 21:23:54 http2: Framer 0xc00050e620: read HEADERS flags=END_HEADERS stream=36971 len=41
2019/04/19 21:23:54 http2: decoded hpack field header field ":method" = "PUT"
2019/04/19 21:23:54 http2: decoded hpack field header field ":path" = "/sinha/home/ashish/Sample/empty_2"
2019/04/19 21:23:54 http2: decoded hpack field header field ":authority" = "localhost:9000"
2019/04/19 21:23:54 http2: decoded hpack field header field ":scheme" = "https"
2019/04/19 21:23:54 http2: decoded hpack field header field "content-md5" = "0ObLjpgreGc9ZUcDuWdW3g=="
2019/04/19 21:23:54 http2: decoded hpack field header field "user-agent" = "MinIO (amd64; amd64) minio-java/dev"
2019/04/19 21:23:54 http2: decoded hpack field header field "x-amz-content-sha256" = "UNSIGNED-PAYLOAD"
2019/04/19 21:23:54 http2: decoded hpack field header field "x-amz-date" = "20190419T155331Z"
2019/04/19 21:23:54 http2: decoded hpack field header field "authorization" = "AWS4-HMAC-SHA256 Credential=minio/20190419/us-east-1/s3/aws4_request, SignedHeaders=content-md5;host;x-amz-content-sha256;x-amz-date, Signature=abafdaf947e7687ca64eb6cba6789b06a3e5dfa0ee4e46c6de5fbcf87bb55668"
2019/04/19 21:23:54 http2: decoded hpack field header field "content-type" = "application/octet-stream"
2019/04/19 21:23:54 http2: decoded hpack field header field "content-length" = "308"
2019/04/19 21:23:54 http2: decoded hpack field header field "accept-encoding" = "gzip"
2019/04/19 21:23:54 http2: Framer 0xc00050e620: wrote RST_STREAM stream=36969 len=4 ErrCode=PROTOCOL_ERROR
2019/04/19 21:23:54 http2: server read frame HEADERS flags=END_HEADERS stream=36971 len=41
2019/04/19 21:23:54 http2: Framer 0xc00050e620: read HEADERS flags=END_HEADERS stream=36973 len=41
2019/04/19 21:23:54 http2: decoded hpack field header field ":method" = "PUT"
2019/04/19 21:23:54 http2: decoded hpack field header field ":path" = "/sinha/home/ashish/Sample/empty_2"
2019/04/19 21:23:54 http2: decoded hpack field header field ":authority" = "localhost:9000"
2019/04/19 21:23:54 http2: decoded hpack field header field ":scheme" = "https"
2019/04/19 21:23:54 http2: decoded hpack field header field "content-md5" = "0ObLjpgreGc9ZUcDuWdW3g=="
2019/04/19 21:23:54 http2: decoded hpack field header field "user-agent" = "MinIO (amd64; amd64) minio-java/dev"
2019/04/19 21:23:54 http2: decoded hpack field header field "x-amz-content-sha256" = "UNSIGNED-PAYLOAD"
2019/04/19 21:23:54 http2: decoded hpack field header field "x-amz-date" = "20190419T155331Z"
2019/04/19 21:23:54 http2: decoded hpack field header field "authorization" = "AWS4-HMAC-SHA256 Credential=minio/20190419/us-east-1/s3/aws4_request, SignedHeaders=content-md5;host;x-amz-content-sha256;x-amz-date, Signature=abafdaf947e7687ca64eb6cba6789b06a3e5dfa0ee4e46c6de5fbcf87bb55668"
2019/04/19 21:23:54 http2: decoded hpack field header field "content-type" = "application/octet-stream"
2019/04/19 21:23:54 http2: decoded hpack field header field "content-length" = "308"
2019/04/19 21:23:54 http2: decoded hpack field header field "accept-encoding" = "gzip"
2019/04/19 21:23:54 http2: Framer 0xc00050e620: wrote RST_STREAM stream=36971 len=4 ErrCode=PROTOCOL_ERROR
2019/04/19 21:23:54 http2: server read frame HEADERS flags=END_HEADERS stream=36973 len=41
2019/04/19 21:23:54 http2: Framer 0xc00050e620: read HEADERS flags=END_HEADERS stream=36975 len=41
2019/04/19 21:23:54 http2: decoded hpack field header field ":method" = "PUT"
2019/04/19 21:23:54 http2: decoded hpack field header field ":path" = "/sinha/home/ashish/Sample/empty_1"
2019/04/19 21:23:54 http2: decoded hpack field header field ":authority" = "localhost:9000"
2019/04/19 21:23:54 http2: decoded hpack field header field ":scheme" = "https"
2019/04/19 21:23:54 http2: decoded hpack field header field "content-md5" = "0ObLjpgreGc9ZUcDuWdW3g=="
2019/04/19 21:23:54 http2: decoded hpack field header field "user-agent" = "MinIO (amd64; amd64) minio-java/dev"
2019/04/19 21:23:54 http2: decoded hpack field header field "x-amz-content-sha256" = "UNSIGNED-PAYLOAD"
2019/04/19 21:23:54 http2: decoded hpack field header field "x-amz-date" = "20190419T155331Z"
2019/04/19 21:23:54 http2: decoded hpack field header field "authorization" = "AWS4-HMAC-SHA256 Credential=minio/20190419/us-east-1/s3/aws4_request, SignedHeaders=content-md5;host;x-amz-content-sha256;x-amz-date, Signature=16f11d231a3e2c989cd1dcfad7b34b4c53411b091b8535a877ddc18f80d36268"
2019/04/19 21:23:54 http2: decoded hpack field header field "content-type" = "application/octet-stream"
2019/04/19 21:23:54 http2: decoded hpack field header field "content-length" = "308"
2019/04/19 21:23:54 http2: decoded hpack field header field "accept-encoding" = "gzip"
2019/04/19 21:23:54 http2: Framer 0xc00050e620: wrote RST_STREAM stream=36973 len=4 ErrCode=PROTOCOL_ERROR
2019/04/19 21:23:54 http2: server read frame HEADERS flags=END_HEADERS stream=36975 len=41
2019/04/19 21:23:54 http2: Framer 0xc00050e620: read HEADERS flags=END_HEADERS stream=36977 len=39
2019/04/19 21:23:54 http2: decoded hpack field header field ":method" = "PUT"
2019/04/19 21:23:54 http2: decoded hpack field header field ":path" = "/sinha/home/ashish/Sample/empty"
2019/04/19 21:23:54 http2: decoded hpack field header field ":authority" = "localhost:9000"
2019/04/19 21:23:54 http2: decoded hpack field header field ":scheme" = "https"
2019/04/19 21:23:54 http2: decoded hpack field header field "content-md5" = "0ObLjpgreGc9ZUcDuWdW3g=="
2019/04/19 21:23:54 http2: decoded hpack field header field "user-agent" = "MinIO (amd64; amd64) minio-java/dev"
2019/04/19 21:23:54 http2: decoded hpack field header field "x-amz-content-sha256" = "UNSIGNED-PAYLOAD"
2019/04/19 21:23:54 http2: decoded hpack field header field "x-amz-date" = "20190419T155331Z"
2019/04/19 21:23:54 http2: decoded hpack field header field "authorization" = "AWS4-HMAC-SHA256 Credential=minio/20190419/us-east-1/s3/aws4_request, SignedHeaders=content-md5;host;x-amz-content-sha256;x-amz-date, Signature=b335653e30400fb6db22eb75e23fde1378f05eef08218bee66bcce558a9b4fc2"
2019/04/19 21:23:54 http2: decoded hpack field header field "content-type" = "application/octet-stream"
2019/04/19 21:23:54 http2: decoded hpack field header field "content-length" = "308"
2019/04/19 21:23:55 http2: decoded hpack field header field "accept-encoding" = "gzip"
2019/04/19 21:23:55 http2: server read frame HEADERS flags=END_HEADERS stream=36977 len=39
2019/04/19 21:23:55 http2: Framer 0xc00050e620: read HEADERS flags=END_HEADERS stream=36979 len=41
2019/04/19 21:23:55 http2: decoded hpack field header field ":method" = "PUT"
2019/04/19 21:23:55 http2: decoded hpack field header field ":path" = "/sinha/home/ashish/Sample/empty_2"
2019/04/19 21:23:55 http2: decoded hpack field header field ":authority" = "localhost:9000"
2019/04/19 21:23:55 http2: decoded hpack field header field ":scheme" = "https"
2019/04/19 21:23:55 http2: decoded hpack field header field "content-md5" = "0ObLjpgreGc9ZUcDuWdW3g=="
2019/04/19 21:23:55 http2: decoded hpack field header field "user-agent" = "MinIO (amd64; amd64) minio-java/dev"
2019/04/19 21:23:55 http2: decoded hpack field header field "x-amz-content-sha256" = "UNSIGNED-PAYLOAD"
2019/04/19 21:23:55 http2: decoded hpack field header field "x-amz-date" = "20190419T155331Z"
2019/04/19 21:23:55 http2: decoded hpack field header field "authorization" = "AWS4-HMAC-SHA256 Credential=minio/20190419/us-east-1/s3/aws4_request, SignedHeaders=content-md5;host;x-amz-content-sha256;x-amz-date, Signature=abafdaf947e7687ca64eb6cba6789b06a3e5dfa0ee4e46c6de5fbcf87bb55668"
2019/04/19 21:23:55 http2: decoded hpack field header field "content-type" = "application/octet-stream"
2019/04/19 21:23:55 http2: decoded hpack field header field "content-length" = "308"
2019/04/19 21:23:55 http2: decoded hpack field header field "accept-encoding" = "gzip"
2019/04/19 21:23:55 http2: Framer 0xc00050e620: wrote RST_STREAM stream=36977 len=4 ErrCode=PROTOCOL_ERROR
2019/04/19 21:23:55 http2: Framer 0xc00050e620: wrote RST_STREAM stream=36975 len=4 ErrCode=PROTOCOL_ERROR
2019/04/19 21:23:55 http2: server read frame HEADERS flags=END_HEADERS stream=36979 len=41
2019/04/19 21:23:55 http2: Framer 0xc00050e620: read HEADERS flags=END_HEADERS stream=36981 len=39
2019/04/19 21:23:55 http2: decoded hpack field header field ":method" = "PUT"
2019/04/19 21:23:55 http2: decoded hpack field header field ":path" = "/sinha/home/ashish/Sample/empty"
2019/04/19 21:23:55 http2: decoded hpack field header field ":authority" = "localhost:9000"
2019/04/19 21:23:55 http2: decoded hpack field header field ":scheme" = "https"
2019/04/19 21:23:55 http2: decoded hpack field header field "content-md5" = "0ObLjpgreGc9ZUcDuWdW3g=="
2019/04/19 21:23:55 http2: decoded hpack field header field "user-agent" = "MinIO (amd64; amd64) minio-java/dev"
2019/04/19 21:23:55 http2: decoded hpack field header field "x-amz-content-sha256" = "UNSIGNED-PAYLOAD"
2019/04/19 21:23:55 http2: decoded hpack field header field "x-amz-date" = "20190419T155331Z"
2019/04/19 21:23:55 http2: decoded hpack field header field "authorization" = "AWS4-HMAC-SHA256 Credential=minio/20190419/us-east-1/s3/aws4_request, SignedHeaders=content-md5;host;x-amz-content-sha256;x-amz-date, Signature=b335653e30400fb6db22eb75e23fde1378f05eef08218bee66bcce558a9b4fc2"
2019/04/19 21:23:55 http2: decoded hpack field header field "content-type" = "application/octet-stream"
2019/04/19 21:23:55 http2: decoded hpack field header field "content-length" = "308"
2019/04/19 21:23:55 http2: decoded hpack field header field "accept-encoding" = "gzip"
2019/04/19 21:23:55 http2: Framer 0xc00050e620: wrote RST_STREAM stream=36979 len=4 ErrCode=PROTOCOL_ERROR
2019/04/19 21:23:55 http2: server read frame HEADERS flags=END_HEADERS stream=36981 len=39
2019/04/19 21:23:55 http2: Framer 0xc00050e620: read HEADERS flags=END_HEADERS stream=36983 len=41
2019/04/19 21:23:55 http2: decoded hpack field header field ":method" = "PUT"
2019/04/19 21:23:55 http2: decoded hpack field header field ":path" = "/sinha/home/ashish/Sample/empty_1"
2019/04/19 21:23:55 http2: decoded hpack field header field ":authority" = "localhost:9000"
2019/04/19 21:23:55 http2: decoded hpack field header field ":scheme" = "https"
2019/04/19 21:23:55 http2: decoded hpack field header field "content-md5" = "0ObLjpgreGc9ZUcDuWdW3g=="
2019/04/19 21:23:55 http2: decoded hpack field header field "user-agent" = "MinIO (amd64; amd64) minio-java/dev"
2019/04/19 21:23:55 http2: decoded hpack field header field "x-amz-content-sha256" = "UNSIGNED-PAYLOAD"
2019/04/19 21:23:55 http2: decoded hpack field header field "x-amz-date" = "20190419T155331Z"
2019/04/19 21:23:55 http2: decoded hpack field header field "authorization" = "AWS4-HMAC-SHA256 Credential=minio/20190419/us-east-1/s3/aws4_request, SignedHeaders=content-md5;host;x-amz-content-sha256;x-amz-date, Signature=16f11d231a3e2c989cd1dcfad7b34b4c53411b091b8535a877ddc18f80d36268"
2019/04/19 21:23:55 http2: decoded hpack field header field "content-type" = "application/octet-stream"
2019/04/19 21:23:55 http2: decoded hpack field header field "content-length" = "308"
2019/04/19 21:23:55 http2: decoded hpack field header field "accept-encoding" = "gzip"
2019/04/19 21:23:55 http2: server read frame HEADERS flags=END_HEADERS stream=36983 len=41
2019/04/19 21:23:55 http2: Framer 0xc00050e620: read HEADERS flags=END_HEADERS stream=36985 len=41
2019/04/19 21:23:55 http2: decoded hpack field header field ":method" = "PUT"
2019/04/19 21:23:55 http2: decoded hpack field header field ":path" = "/sinha/home/ashish/Sample/empty_2"
2019/04/19 21:23:55 http2: decoded hpack field header field ":authority" = "localhost:9000"
2019/04/19 21:23:55 http2: decoded hpack field header field ":scheme" = "https"
2019/04/19 21:23:55 http2: decoded hpack field header field "content-md5" = "0ObLjpgreGc9ZUcDuWdW3g=="
2019/04/19 21:23:55 http2: decoded hpack field header field "user-agent" = "MinIO (amd64; amd64) minio-java/dev"
2019/04/19 21:23:55 http2: decoded hpack field header field "x-amz-content-sha256" = "UNSIGNED-PAYLOAD"
2019/04/19 21:23:55 http2: decoded hpack field header field "x-amz-date" = "20190419T155331Z"
2019/04/19 21:23:55 http2: decoded hpack field header field "authorization" = "AWS4-HMAC-SHA256 Credential=minio/20190419/us-east-1/s3/aws4_request, SignedHeaders=content-md5;host;x-amz-content-sha256;x-amz-date, Signature=abafdaf947e7687ca64eb6cba6789b06a3e5dfa0ee4e46c6de5fbcf87bb55668"
2019/04/19 21:23:55 http2: decoded hpack field header field "content-type" = "application/octet-stream"
2019/04/19 21:23:55 http2: decoded hpack field header field "content-length" = "308"
2019/04/19 21:23:55 http2: decoded hpack field header field "accept-encoding" = "gzip"
2019/04/19 21:23:55 http2: Framer 0xc00050e620: wrote RST_STREAM stream=36981 len=4 ErrCode=PROTOCOL_ERROR
2019/04/19 21:23:55 http2: Framer 0xc00050e620: wrote RST_STREAM stream=36983 len=4 ErrCode=PROTOCOL_ERROR
2019/04/19 21:23:55 http2: server read frame HEADERS flags=END_HEADERS stream=36985 len=41
2019/04/19 21:23:55 http2: Framer 0xc00050e620: read HEADERS flags=END_HEADERS stream=36987 len=39
2019/04/19 21:23:55 http2: decoded hpack field header field ":method" = "PUT"
2019/04/19 21:23:55 http2: decoded hpack field header field ":path" = "/sinha/home/ashish/Sample/empty"
2019/04/19 21:23:55 http2: decoded hpack field header field ":authority" = "localhost:9000"
2019/04/19 21:23:55 http2: decoded hpack field header field ":scheme" = "https"
2019/04/19 21:23:55 http2: decoded hpack field header field "content-md5" = "0ObLjpgreGc9ZUcDuWdW3g=="
2019/04/19 21:23:55 http2: decoded hpack field header field "user-agent" = "MinIO (amd64; amd64) minio-java/dev"
2019/04/19 21:23:55 http2: decoded hpack field header field "x-amz-content-sha256" = "UNSIGNED-PAYLOAD"
2019/04/19 21:23:55 http2: decoded hpack field header field "x-amz-date" = "20190419T155331Z"
2019/04/19 21:23:55 http2: decoded hpack field header field "authorization" = "AWS4-HMAC-SHA256 Credential=minio/20190419/us-east-1/s3/aws4_request, SignedHeaders=content-md5;host;x-amz-content-sha256;x-amz-date, Signature=b335653e30400fb6db22eb75e23fde1378f05eef08218bee66bcce558a9b4fc2"
2019/04/19 21:23:55 http2: decoded hpack field header field "content-type" = "application/octet-stream"
2019/04/19 21:23:55 http2: decoded hpack field header field "content-length" = "308"
2019/04/19 21:23:55 http2: decoded hpack field header field "accept-encoding" = "gzip"
2019/04/19 21:23:55 http2: Framer 0xc00050e620: wrote RST_STREAM stream=36985 len=4 ErrCode=PROTOCOL_ERROR
2019/04/19 21:23:55 http2: server read frame HEADERS flags=END_HEADERS stream=36987 len=39
2019/04/19 21:23:55 http2: Framer 0xc00050e620: read HEADERS flags=END_HEADERS stream=36989 len=41
2019/04/19 21:23:55 http2: decoded hpack field header field ":method" = "PUT"
2019/04/19 21:23:55 http2: decoded hpack field header field ":path" = "/sinha/home/ashish/Sample/empty_1"
2019/04/19 21:23:55 http2: decoded hpack field header field ":authority" = "localhost:9000"
2019/04/19 21:23:55 http2: decoded hpack field header field ":scheme" = "https"
2019/04/19 21:23:55 http2: decoded hpack field header field "content-md5" = "0ObLjpgreGc9ZUcDuWdW3g=="
2019/04/19 21:23:55 http2: decoded hpack field header field "user-agent" = "MinIO (amd64; amd64) minio-java/dev"
2019/04/19 21:23:55 http2: decoded hpack field header field "x-amz-content-sha256" = "UNSIGNED-PAYLOAD"
2019/04/19 21:23:55 http2: decoded hpack field header field "x-amz-date" = "20190419T155331Z"
2019/04/19 21:23:55 http2: decoded hpack field header field "authorization" = "AWS4-HMAC-SHA256 Credential=minio/20190419/us-east-1/s3/aws4_request, SignedHeaders=content-md5;host;x-amz-content-sha256;x-amz-date, Signature=16f11d231a3e2c989cd1dcfad7b34b4c53411b091b8535a877ddc18f80d36268"
2019/04/19 21:23:55 http2: decoded hpack field header field "content-type" = "application/octet-stream"
2019/04/19 21:23:55 http2: decoded hpack field header field "content-length" = "308"
2019/04/19 21:23:55 http2: decoded hpack field header field "accept-encoding" = "gzip"
2019/04/19 21:23:55 http2: Framer 0xc00050e620: wrote RST_STREAM stream=36987 len=4 ErrCode=PROTOCOL_ERROR
2019/04/19 21:23:55 http2: server read frame HEADERS flags=END_HEADERS stream=36989 len=41
2019/04/19 21:23:55 http2: Framer 0xc00050e620: read HEADERS flags=END_HEADERS stream=36991 len=39
2019/04/19 21:23:55 http2: decoded hpack field header field ":method" = "PUT"
2019/04/19 21:23:55 http2: decoded hpack field header field ":path" = "/sinha/home/ashish/Sample/empty"
2019/04/19 21:23:55 http2: decoded hpack field header field ":authority" = "localhost:9000"
2019/04/19 21:23:55 http2: decoded hpack field header field ":scheme" = "https"
2019/04/19 21:23:55 http2: decoded hpack field header field "content-md5" = "0ObLjpgreGc9ZUcDuWdW3g=="
2019/04/19 21:23:55 http2: decoded hpack field header field "user-agent" = "MinIO (amd64; amd64) minio-java/dev"
2019/04/19 21:23:55 http2: decoded hpack field header field "x-amz-content-sha256" = "UNSIGNED-PAYLOAD"
2019/04/19 21:23:55 http2: decoded hpack field header field "x-amz-date" = "20190419T155331Z"
2019/04/19 21:23:55 http2: decoded hpack field header field "authorization" = "AWS4-HMAC-SHA256 Credential=minio/20190419/us-east-1/s3/aws4_request, SignedHeaders=content-md5;host;x-amz-content-sha256;x-amz-date, Signature=b335653e30400fb6db22eb75e23fde1378f05eef08218bee66bcce558a9b4fc2"
2019/04/19 21:23:55 http2: decoded hpack field header field "content-type" = "application/octet-stream"
2019/04/19 21:23:55 http2: decoded hpack field header field "content-length" = "308"
2019/04/19 21:23:55 http2: decoded hpack field header field "accept-encoding" = "gzip"
2019/04/19 21:23:55 http2: Framer 0xc00050e620: wrote RST_STREAM stream=36989 len=4 ErrCode=PROTOCOL_ERROR
2019/04/19 21:23:55 http2: server read frame HEADERS flags=END_HEADERS stream=36991 len=39
2019/04/19 21:23:55 http2: Framer 0xc00050e620: read HEADERS flags=END_HEADERS stream=36993 len=41
2019/04/19 21:23:55 http2: decoded hpack field header field ":method" = "PUT"
2019/04/19 21:23:55 http2: decoded hpack field header field ":path" = "/sinha/home/ashish/Sample/empty_2"
2019/04/19 21:23:55 http2: decoded hpack field header field ":authority" = "localhost:9000"
2019/04/19 21:23:55 http2: decoded hpack field header field ":scheme" = "https"
2019/04/19 21:23:55 http2: decoded hpack field header field "content-md5" = "0ObLjpgreGc9ZUcDuWdW3g=="
2019/04/19 21:23:55 http2: decoded hpack field header field "user-agent" = "MinIO (amd64; amd64) minio-java/dev"
2019/04/19 21:23:55 http2: decoded hpack field header field "x-amz-content-sha256" = "UNSIGNED-PAYLOAD"
2019/04/19 21:23:55 http2: decoded hpack field header field "x-amz-date" = "20190419T155331Z"
2019/04/19 21:23:55 http2: decoded hpack field header field "authorization" = "AWS4-HMAC-SHA256 Credential=minio/20190419/us-east-1/s3/aws4_request, SignedHeaders=content-md5;host;x-amz-content-sha256;x-amz-date, Signature=abafdaf947e7687ca64eb6cba6789b06a3e5dfa0ee4e46c6de5fbcf87bb55668"
2019/04/19 21:23:55 http2: decoded hpack field header field "content-type" = "application/octet-stream"
2019/04/19 21:23:55 http2: decoded hpack field header field "content-length" = "308"
2019/04/19 21:23:55 http2: decoded hpack field header field "accept-encoding" = "gzip"
2019/04/19 21:23:55 http2: Framer 0xc00050e620: wrote RST_STREAM stream=36991 len=4 ErrCode=PROTOCOL_ERROR
2019/04/19 21:23:55 http2: server read frame HEADERS flags=END_HEADERS stream=36993 len=41
2019/04/19 21:23:55 http2: Framer 0xc00050e620: read HEADERS flags=END_HEADERS stream=36995 len=41
2019/04/19 21:23:55 http2: decoded hpack field header field ":method" = "PUT"
2019/04/19 21:23:55 http2: decoded hpack field header field ":path" = "/sinha/home/ashish/Sample/empty_1"
2019/04/19 21:23:55 http2: decoded hpack field header field ":authority" = "localhost:9000"
2019/04/19 21:23:55 http2: decoded hpack field header field ":scheme" = "https"
2019/04/19 21:23:55 http2: decoded hpack field header field "content-md5" = "0ObLjpgreGc9ZUcDuWdW3g=="
2019/04/19 21:23:55 http2: decoded hpack field header field "user-agent" = "MinIO (amd64; amd64) minio-java/dev"
2019/04/19 21:23:55 http2: decoded hpack field header field "x-amz-content-sha256" = "UNSIGNED-PAYLOAD"
2019/04/19 21:23:55 http2: decoded hpack field header field "x-amz-date" = "20190419T155331Z"
2019/04/19 21:23:55 http2: decoded hpack field header field "authorization" = "AWS4-HMAC-SHA256 Credential=minio/20190419/us-east-1/s3/aws4_request, SignedHeaders=content-md5;host;x-amz-content-sha256;x-amz-date, Signature=16f11d231a3e2c989cd1dcfad7b34b4c53411b091b8535a877ddc18f80d36268"
2019/04/19 21:23:55 http2: decoded hpack field header field "content-type" = "application/octet-stream"
2019/04/19 21:23:55 http2: decoded hpack field header field "content-length" = "308"
2019/04/19 21:23:55 http2: decoded hpack field header field "accept-encoding" = "gzip"
2019/04/19 21:23:55 http2: Framer 0xc00050e620: wrote RST_STREAM stream=36993 len=4 ErrCode=PROTOCOL_ERROR

API: SYSTEM()
Time: 21:23:55 IST 04/19/2019
Error: timed out. some connections are still active. doing abnormal shutdown
       1: cmd/signals.go:53:cmd.handleSignals.func2()
       2: cmd/signals.go:79:cmd.handleSignals()
       3: cmd/server-main.go:380:cmd.serverMain()
2019/04/19 21:23:55 http2: server read frame HEADERS flags=END_HEADERS stream=36995 len=41
2019/04/19 21:23:55 http2: Framer 0xc00050e620: read HEADERS flags=END_HEADERS stream=36997 len=39
2019/04/19 21:23:55 http2: decoded hpack field header field ":method" = "PUT"
2019/04/19 21:23:55 http2: decoded hpack field header field ":path" = "/sinha/home/ashish/Sample/empty"
2019/04/19 21:23:55 http2: decoded hpack field header field ":authority" = "localhost:9000"
2019/04/19 21:23:55 http2: decoded hpack field header field ":scheme" = "https"
agnivade commented 5 years ago

@bradfitz @fraenkel

fraenkel commented 5 years ago

@sinhaashish Next time please give us exact steps to reproduce the issue. The code above is incomplete and knowing to use the 6.0.5 version was not very obvious. In the end, my version works just fine. I uploaded 7 files, 2 were the minio java client jars, 4 were the source and class files, and then a dummy file.

sinhaashish commented 5 years ago

@sinhaashish Next time please give us exact steps to reproduce the issue. The code above is incomplete and knowing to use the 6.0.5 version was not very obvious. In the end, my version works just fine. I uploaded 7 files, 2 were the minio java client jars, 4 were the source and class files, and then a dummy file.

@fraenkel : Can you try it a multiple of times, as the issue is sporadic for me too.

fraenkel commented 5 years ago

@sinhaashish I have reproduced the issue. I am still determining the root cause. There are multiple issues going on here which is why it will take some time.

I see cases where the client side is reusing a closed stream and the server eventually says to GOAWAY. After that point, it becomes a constant barage of PROTOCOL_ERROR which then subsides. New connections are created until we hit another issue which is exceeded the number of concurrent streams. This is when the server side goes into a hard loop.

I will let you know more as I dig deeper.

fraenkel commented 5 years ago

Working backwards, the crazy looping looks like a minio issue which I have no plans to debug. The call stack is about 45 calls deep and the majority is minio and gorilla. Most of the threads are stuck waiting to read data from the body. This is when the number of concurrent requests is exceeded.

Other times, I see minio also stuck trying to grab locks during PutObject. This too is not something I will debug.

The only remaining investigation is the very first issue that occurs.

fraenkel commented 5 years ago

The very first error that occurs looks like a client initiated issue.

2019/04/20 14:31:10 http2: framer 0xc0004441c0: wrote data stream=11 len=267 data="<?xml version=\"1.0\" encoding=\"utf-8\"?>\n<initiatemultipartuploadresult xmlns=\"http://s3.amazonaws.com/doc/2006-03-01/\"><bucket>my-bucketname</bucket><key>minio-6.0.6-all.jar</key><uploadid>af74c215-472d-4628-b1e6-09cb8c20f32b</uploadid></initiatemultipartup" (11 bytes omitted)
2019/04/20 14:31:10 http2: Framer 0xc0004441c0: wrote DATA flags=END_STREAM stream=11 len=0 data=""
2019/04/20 14:31:10 http2: Framer 0xc0004441c0: read GOAWAY len=8 LastStreamID=0 ErrCode=PROTOCOL_ERROR Debug=""

After the new connection is established, we then run into the issues listed above.

So far I don't see anything that points to an issue on the server side. Someone needs to investigate the client issue first.

harshavardhana commented 5 years ago

What does it mean by client initiated issue ? Are you saying okhttp is buggy here ?

fraenkel commented 5 years ago

I can only tell you what I see. Someone would have to debug the client side to see what is going on.

harshavardhana commented 5 years ago

I can only tell you what I see. Someone would have to debug the client side to see what is going on.

Can you tell me exactly what that might be? - @fraenkel would like to share this with okhttp project?

harshavardhana commented 5 years ago

Working backwards, the crazy looping looks like a minio issue which I have no plans to debug. The call stack is about 45 calls deep and the majority is minio and gorilla. Most of the threads are stuck waiting to read data from the body. This is when the number of concurrent requests is exceeded.

Other times, I see minio also stuck trying to grab locks during PutObject. This too is not something I will debug.

@fraenkel in this scenario the cause is HTTP 2.0 failing with HTTP 1.1 we don't see these issues at all. NOTE: nodes are also communicating over HTTP 2.0 with TLS connections as well as clients.