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

gRPC upstream with TLS doens't work #9665

Closed
qiwzhang opened this issue Jan 13, 2020 · 14 comments
Closed

gRPC upstream with TLS doens't work #9665

qiwzhang opened this issue Jan 13, 2020 · 14 comments
Labels
investigate Potential bug that needs verification

Comments

@qiwzhang
Copy link
Contributor

qiwzhang commented Jan 13, 2020 •
edited
Loading

Title: gRPC upstream with TLS doens't work

Description:
I tried to setup Envoy proxy to talk to gRPC service deployed in Google Cloud Run, it did not work.

Repro steps:

  • deployed a grpc service to Google Cloud Run and use a gRpc client to verify it works.
  • then deploy a envoy proxy with upstream to the Cloud Run gRPC service.
  • point same gRPC client to the envoy listening port. (downstream without TLS, but upstream is using TLS).
  • the grpc call fails with error "upstream connect error or disconnect/reset before headers. reset reason: connection termination"

Config:

{
  "staticResources": {
    "listeners": [
      {
        "address": {
          "socketAddress": {
            "address": "0.0.0.0",
            "portValue": 8080
          }
        },
        "filterChains": [
          {
            "filters": [
              {
                "name": "envoy.http_connection_manager",
                "typedConfig": {
                  "@type": "type.googleapis.com/envoy.config.filter.network.http_connection_manager.v2.HttpConnectionManager",
                  "statPrefix": "ingress_http",
                  "routeConfig": {
                    "name": "local_route",
                    "virtualHosts": [
                      {
                        "name": "backend",
                        "domains": [
                          "*"
                        ],
                        "routes": [
                          {
                            "match": {
                              "prefix": "/"
                            },
                            "route": {
                              "cluster": "backend",
                              "hostRewrite": "grpc-echo-oxouww7xzq-uc.a.run.app"
                            }
                          }
                        ]
                      }
                    ]
                  },
                  "httpFilters": [
                    {
                      "name": "envoy.router",
                      "typedConfig": {
                        "@type": "type.googleapis.com/envoy.config.filter.http.router.v2.Router"
                      }
                    }
                  ]
                }
              }
            ]
          }
        ]
      }
    ],
   "clusters": [
      {
        "name": "backend",
        "type": "STRICT_DNS",
        "connectTimeout": "20s",
        "loadAssignment": {
          "clusterName": "grpc-echo-oxouww7xzq-uc.a.run.app",
          "endpoints": [
            {
              "lbEndpoints": [
                {
                  "endpoint": {
                    "address": {
                      "socketAddress": {
                        "address": "grpc-echo-oxouww7xzq-uc.a.run.app",
                        "portValue": 443
                      }
                    }
                  }
                }
              ]
            }
          ]
        },
        "dnsLookupFamily": "V4_ONLY",
        "transportSocket": {
          "name": "envoy.transport_sockets.tls",
          "typedConfig": {
            "@type": "type.googleapis.com/envoy.api.v2.auth.UpstreamTlsContext",
            "commonTlsContext": {
              "validationContext": {
                "trustedCa": {
                  "filename": "/etc/ssl/certs/ca-certificates.crt"
                }
              }
            },
            "sni": "grpc-echo-oxouww7xzq-uc.a.run.app"
          }
        },
        "http2ProtocolOptions": {}
      }
    ]
  },
  "admin": {
     "access_log_path": "/dev/null",
     "address": {
        "socket_address": {
            "address": "0.0.0.0",
            "port_value": 8001
         }
     }
  }
}

Logs:
The log with "trace" level

[2020-01-13 18:58:11.892][20584][debug][conn_handler] [external/envoy/source/server/connection_handler_impl.cc:335] [C0] new connection
[2020-01-13 18:58:11.892][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:458] [C0] socket event: 2
[2020-01-13 18:58:11.892][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:546] [C0] write ready
[2020-01-13 18:58:11.892][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:458] [C0] socket event: 3
[2020-01-13 18:58:11.892][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:546] [C0] write ready
[2020-01-13 18:58:11.892][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:496] [C0] read ready
[2020-01-13 18:58:11.892][20584][trace][connection] [external/envoy/source/common/network/raw_buffer_socket.cc:24] [C0] read returns: 406
[2020-01-13 18:58:11.892][20584][trace][connection] [external/envoy/source/common/network/raw_buffer_socket.cc:38] [C0] read error: Resource temporarily unavailable
[2020-01-13 18:58:11.892][20584][debug][http2] [external/envoy/source/common/http/http2/codec_impl.cc:912] [C0] setting stream-level initial window size to 268435456
[2020-01-13 18:58:11.892][20584][debug][http2] [external/envoy/source/common/http/http2/codec_impl.cc:934] [C0] updating connection-level initial window size to 268435456
[2020-01-13 18:58:11.892][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:405] [C0] dispatching 406 bytes
[2020-01-13 18:58:11.892][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:468] [C0] about to recv frame type=4, flags=0
[2020-01-13 18:58:11.892][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1190] [C0] track inbound frame type=4 flags=0 length=36 padding_length=0
[2020-01-13 18:58:11.892][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:483] [C0] recv frame type=4
[2020-01-13 18:58:11.892][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:468] [C0] about to recv frame type=8, flags=0
[2020-01-13 18:58:11.892][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1190] [C0] track inbound frame type=8 flags=0 length=4 padding_length=0
[2020-01-13 18:58:11.892][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:483] [C0] recv frame type=8
[2020-01-13 18:58:11.892][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:468] [C0] about to recv frame type=6, flags=0
[2020-01-13 18:58:11.892][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1190] [C0] track inbound frame type=6 flags=0 length=8 padding_length=0
[2020-01-13 18:58:11.892][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:483] [C0] recv frame type=6
[2020-01-13 18:58:11.892][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:468] [C0] about to recv frame type=1, flags=4
[2020-01-13 18:58:11.892][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1190] [C0] track inbound frame type=1 flags=4 length=243 padding_length=0
[2020-01-13 18:58:11.892][20584][debug][http] [external/envoy/source/common/http/conn_manager_impl.cc:259] [C0] new stream
[2020-01-13 18:58:11.893][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:483] [C0] recv frame type=1
[2020-01-13 18:58:11.894][20584][debug][http] [external/envoy/source/common/http/conn_manager_impl.cc:708] [C0][S9716606764335229993] request headers complete (end_stream=false):
':scheme', 'http'
':method', 'POST'
':authority', 'localhost:8080'
':path', '/test.grpc.Test/Echo'
'te', 'trailers'
'content-type', 'application/grpc'
'user-agent', 'grpc-c++/1.22.0-dev grpc-c/7.0.0 (linux; chttp2; gale)'
'grpc-accept-encoding', 'identity,deflate,gzip'
'accept-encoding', 'identity,gzip'

[2020-01-13 18:58:11.894][20584][debug][router] [external/envoy/source/common/router/router.cc:438] [C0][S9716606764335229993] cluster 'backend' match for URL '/test.grpc.Test/Echo'
[2020-01-13 18:58:11.894][20584][debug][router] [external/envoy/source/common/router/router.cc:553] [C0][S9716606764335229993] router decoding headers:
':scheme', 'https'
':method', 'POST'
':authority', 'grpc-echo-oxouww7xzq-uc.a.run.app'
':path', '/test.grpc.Test/Echo'
'te', 'trailers'
'content-type', 'application/grpc'
'user-agent', 'grpc-c++/1.22.0-dev grpc-c/7.0.0 (linux; chttp2; gale)'
'grpc-accept-encoding', 'identity,deflate,gzip'
'accept-encoding', 'identity,gzip'
'x-forwarded-proto', 'http'
'x-request-id', 'ab412298-cf6d-46b0-83f5-177b1cec9006'
'x-envoy-expected-rq-timeout-ms', '15000'

[2020-01-13 18:58:11.894][20584][debug][client] [external/envoy/source/common/http/codec_client.cc:31] [C1] connecting
[2020-01-13 18:58:11.894][20584][debug][connection] [external/envoy/source/common/network/connection_impl.cc:707] [C1] connecting to 216.239.36.53:443
[2020-01-13 18:58:11.894][20584][debug][connection] [external/envoy/source/common/network/connection_impl.cc:716] [C1] connection in progress
[2020-01-13 18:58:11.894][20584][debug][http2] [external/envoy/source/common/http/http2/codec_impl.cc:912] [C1] setting stream-level initial window size to 268435456
[2020-01-13 18:58:11.894][20584][debug][http2] [external/envoy/source/common/http/http2/codec_impl.cc:934] [C1] updating connection-level initial window size to 268435456
[2020-01-13 18:58:11.894][20584][debug][pool] [external/envoy/source/common/http/conn_pool_base.cc:20] queueing request due to no available connections
[2020-01-13 18:58:11.894][20584][trace][http] [external/envoy/source/common/http/conn_manager_impl.cc:959] [C0][S9716606764335229993] decode headers called: filter=0x562c8093cf00 status=1
[2020-01-13 18:58:11.894][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:468] [C0] about to recv frame type=8, flags=0
[2020-01-13 18:58:11.894][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1190] [C0] track inbound frame type=8 flags=0 length=4 padding_length=0
[2020-01-13 18:58:11.894][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:483] [C0] recv frame type=8
[2020-01-13 18:58:11.894][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:468] [C0] about to recv frame type=0, flags=1
[2020-01-13 18:58:11.894][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:483] [C0] recv frame type=0
[2020-01-13 18:58:11.894][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1190] [C0] track inbound frame type=0 flags=1 length=20 padding_length=0
[2020-01-13 18:58:11.894][20584][debug][http] [external/envoy/source/common/http/conn_manager_impl.cc:1250] [C0][S9716606764335229993] request end stream
[2020-01-13 18:58:11.894][20584][trace][router] [external/envoy/source/common/router/router.cc:1478] [C0][S9716606764335229993] buffering 20 bytes
[2020-01-13 18:58:11.894][20584][trace][http] [external/envoy/source/common/http/conn_manager_impl.cc:1098] [C0][S9716606764335229993] decode data called: filter=0x562c8093cf00 status=3
[2020-01-13 18:58:11.894][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:468] [C0] about to recv frame type=8, flags=0
[2020-01-13 18:58:11.894][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:1190] [C0] track inbound frame type=8 flags=0 length=4 padding_length=0
[2020-01-13 18:58:11.894][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:483] [C0] recv frame type=8
[2020-01-13 18:58:11.894][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:424] [C0] dispatched 406 bytes
[2020-01-13 18:58:11.894][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:666] [C0] about to send frame type=4, flags=0
[2020-01-13 18:58:11.894][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:720] [C0] send data: bytes=15
[2020-01-13 18:58:11.894][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:394] [C0] writing 15 bytes, end_stream false
[2020-01-13 18:58:11.894][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:608] [C0] sent frame type=4
[2020-01-13 18:58:11.894][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:666] [C0] about to send frame type=4, flags=1
[2020-01-13 18:58:11.894][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:720] [C0] send data: bytes=9
[2020-01-13 18:58:11.894][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:394] [C0] writing 9 bytes, end_stream false
[2020-01-13 18:58:11.894][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:608] [C0] sent frame type=4
[2020-01-13 18:58:11.894][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:666] [C0] about to send frame type=6, flags=1
[2020-01-13 18:58:11.894][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:720] [C0] send data: bytes=17
[2020-01-13 18:58:11.894][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:394] [C0] writing 17 bytes, end_stream false
[2020-01-13 18:58:11.894][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:608] [C0] sent frame type=6
[2020-01-13 18:58:11.894][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:666] [C0] about to send frame type=8, flags=0
[2020-01-13 18:58:11.894][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:720] [C0] send data: bytes=13
[2020-01-13 18:58:11.894][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:394] [C0] writing 13 bytes, end_stream false
[2020-01-13 18:58:11.894][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:608] [C0] sent frame type=8
[2020-01-13 18:58:11.894][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:458] [C0] socket event: 2
[2020-01-13 18:58:11.894][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:546] [C0] write ready
[2020-01-13 18:58:11.894][20584][trace][connection] [external/envoy/source/common/network/raw_buffer_socket.cc:67] [C0] write returns: 54
[2020-01-13 18:58:11.894][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:458] [C0] socket event: 2
[2020-01-13 18:58:11.894][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:546] [C0] write ready
[2020-01-13 18:58:11.897][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:458] [C1] socket event: 2
[2020-01-13 18:58:11.897][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:546] [C1] write ready
[2020-01-13 18:58:11.898][20584][debug][connection] [external/envoy/source/common/network/connection_impl.cc:555] [C1] connected
[2020-01-13 18:58:11.898][20584][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:191] [C1] handshake expecting read
[2020-01-13 18:58:11.899][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:458] [C1] socket event: 3
[2020-01-13 18:58:11.899][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:546] [C1] write ready
[2020-01-13 18:58:11.899][20584][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:191] [C1] handshake expecting read
[2020-01-13 18:58:11.899][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:496] [C1] read ready
[2020-01-13 18:58:11.899][20584][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:191] [C1] handshake expecting read
[2020-01-13 18:58:11.899][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:458] [C1] socket event: 3
[2020-01-13 18:58:11.899][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:546] [C1] write ready
[2020-01-13 18:58:11.899][20584][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:176] [C1] handshake complete
[2020-01-13 18:58:11.900][20584][debug][client] [external/envoy/source/common/http/codec_client.cc:69] [C1] connected
[2020-01-13 18:58:11.900][20584][debug][pool] [external/envoy/source/common/http/http2/conn_pool.cc:98] [C1] creating stream
[2020-01-13 18:58:11.900][20584][debug][router] [external/envoy/source/common/router/router.cc:1621] [C0][S9716606764335229993] pool ready
[2020-01-13 18:58:11.900][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:720] [C1] send data: bytes=24
[2020-01-13 18:58:11.900][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:394] [C1] writing 24 bytes, end_stream false
[2020-01-13 18:58:11.900][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:666] [C1] about to send frame type=4, flags=0
[2020-01-13 18:58:11.900][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:720] [C1] send data: bytes=21
[2020-01-13 18:58:11.900][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:394] [C1] writing 21 bytes, end_stream false
[2020-01-13 18:58:11.900][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:608] [C1] sent frame type=4
[2020-01-13 18:58:11.900][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:666] [C1] about to send frame type=8, flags=0
[2020-01-13 18:58:11.900][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:720] [C1] send data: bytes=13
[2020-01-13 18:58:11.900][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:394] [C1] writing 13 bytes, end_stream false
[2020-01-13 18:58:11.900][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:608] [C1] sent frame type=8
[2020-01-13 18:58:11.900][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:666] [C1] about to send frame type=1, flags=4
[2020-01-13 18:58:11.900][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:720] [C1] send data: bytes=253
[2020-01-13 18:58:11.900][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:394] [C1] writing 253 bytes, end_stream false
[2020-01-13 18:58:11.900][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:608] [C1] sent frame type=1
[2020-01-13 18:58:11.900][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:394] [C1] writing 29 bytes, end_stream false
[2020-01-13 18:58:11.900][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:608] [C1] sent frame type=0
[2020-01-13 18:58:11.900][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:546] [C1] write ready
[2020-01-13 18:58:11.900][20584][trace][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:259] [C1] ssl write returns: 340
[2020-01-13 18:58:11.900][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:496] [C1] read ready
[2020-01-13 18:58:11.900][20584][trace][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:80] [C1] ssl read returns: -1
[2020-01-13 18:58:11.900][20584][trace][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:155] [C1] ssl read 0 bytes into 0 slices
[2020-01-13 18:58:11.900][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:458] [C1] socket event: 2
[2020-01-13 18:58:11.900][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:546] [C1] write ready
[2020-01-13 18:58:11.900][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:458] [C1] socket event: 3
[2020-01-13 18:58:11.900][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:546] [C1] write ready
[2020-01-13 18:58:11.900][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:496] [C1] read ready
[2020-01-13 18:58:11.900][20584][trace][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:80] [C1] ssl read returns: 1379
[2020-01-13 18:58:11.900][20584][trace][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:80] [C1] ssl read returns: 333
[2020-01-13 18:58:11.900][20584][trace][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:80] [C1] ssl read returns: 0
[2020-01-13 18:58:11.900][20584][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:226] [C1] 
[2020-01-13 18:58:11.900][20584][trace][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:155] [C1] ssl read 1712 bytes into 1 slices
[2020-01-13 18:58:11.900][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:405] [C1] dispatching 1712 bytes
[2020-01-13 18:58:11.900][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:424] [C1] dispatched 1712 bytes
[2020-01-13 18:58:11.900][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:666] [C1] about to send frame type=7, flags=0
[2020-01-13 18:58:11.900][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:720] [C1] send data: bytes=34
[2020-01-13 18:58:11.900][20584][trace][connection] [external/envoy/source/common/network/connection_impl.cc:394] [C1] writing 34 bytes, end_stream false
[2020-01-13 18:58:11.900][20584][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:608] [C1] sent frame type=7
[2020-01-13 18:58:11.900][20584][debug][http2] [external/envoy/source/common/http/http2/codec_impl.cc:611] [C1] sent goaway code=1
[2020-01-13 18:58:11.900][20584][debug][client] [external/envoy/source/common/http/codec_client.cc:124] [C1] protocol error: The user callback function failed
[2020-01-13 18:58:11.900][20584][debug][connection] [external/envoy/source/common/network/connection_impl.cc:100] [C1] closing data_to_write=34 type=1
[2020-01-13 18:58:11.900][20584][trace][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:259] [C1] ssl write returns: 34
[2020-01-13 18:58:11.900][20584][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:298] [C1] SSL shutdown: rc=0
[2020-01-13 18:58:11.900][20584][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:226] [C1] 
[2020-01-13 18:58:11.900][20584][debug][connection] [external/envoy/source/common/network/connection_impl.cc:189] [C1] closing socket: 1
[2020-01-13 18:58:11.900][20584][debug][client] [external/envoy/source/common/http/codec_client.cc:88] [C1] disconnect. resetting 1 pending requests
[2020-01-13 18:58:11.900][20584][debug][client] [external/envoy/source/common/http/codec_client.cc:111] [C1] request reset
[2020-01-13 18:58:11.900][20584][trace][main] [external/envoy/source/common/event/dispatcher_impl.cc:160] item added to deferred deletion list (size=1)
[2020-01-13 18:58:11.900][20584][debug][pool] [external/envoy/source/common/http/http2/conn_pool.cc:236] [C1] destroying stream: 0 remaining
[2020-01-13 18:58:11.900][20584][debug][router] [external/envoy/source/common/router/router.cc:914] [C0][S9716606764335229993] upstream reset: reset reason connection termination
[2020-01-13 18:58:11.900][20584][debug][http] [external/envoy/source/common/http/conn_manager_impl.cc:1347] [C0][S9716606764335229993] Sending local reply with details upstream_reset_before_response_started{connection termination}
[2020-01-13 18:58:11.900][20584][debug][http] [external/envoy/source/common/http/conn_manager_impl.cc:1545] [C0][S9716606764335229993] encoding headers via codec (end_stream=true):
':status', '200'
'content-type', 'application/grpc'
'grpc-status', '14'
'grpc-message', 'upstream connect error or disconnect/reset before headers. reset reason: connection termination'
'date', 'Mon, 13 Jan 2020 18:58:11 GMT'
'server', 'envoy'

Additional info:
gRPC language: both grpc client and server are using c++.
gRPC log:
For the failed request, there is not log in the grpc server, it seems that the request did not reach grpc server, it fails in the TLS negotiation between Envoy upstream and Cloud Run.
@qiwzhang
Copy link
Contributor Author

@lizan , @PiotrSikora , @htuch could you help? Thanks

@PiotrSikora
Copy link
Contributor

@qiwzhang it looks that TLS and HTTP/2 connections are established correctly, but then Envoy sends GOAWAY frame to upstream and terminates connection, for some reason. I cannot tell from the logs what's wrong.

@qiwzhang
Copy link
Contributor Author

@PiotrSikora will a tcpdump help? I can capture a tcpdump for you

@PiotrSikora
Copy link
Contributor

No, tcpdump output will be encrypted. Do you have logs from the Cloud Run instance?

@qiwzhang
Copy link
Contributor Author

no much log from the instance. It did not show anything from the cloud run instance.

@qiwzhang
Copy link
Contributor Author

If a grpc call bypassing envoy proxy, it will have a success log entry in the instance. A grpc request with the proxy doesn't show anything in the instance log.

@qiwzhang
Copy link
Contributor Author

@PiotrSikora @lizan

Here is trace log with more nghttp2 log entries:

[2020-01-13 23:21:31.583][32261][trace][connection] [source/common/network/connection_impl.cc:466] [C1] socket event: 2
[2020-01-13 23:21:31.583][32261][trace][connection] [source/common/network/connection_impl.cc:554] [C1] write ready
[2020-01-13 23:21:31.584][32261][debug][connection] [source/common/network/connection_impl.cc:563] [C1] connected
[2020-01-13 23:21:31.584][32261][debug][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:191] [C1] handshake expecting read
[2020-01-13 23:21:31.585][32261][trace][connection] [source/common/network/connection_impl.cc:466] [C1] socket event: 3
[2020-01-13 23:21:31.585][32261][trace][connection] [source/common/network/connection_impl.cc:554] [C1] write ready
[2020-01-13 23:21:31.587][32261][debug][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:191] [C1] handshake expecting read
[2020-01-13 23:21:31.587][32261][trace][connection] [source/common/network/connection_impl.cc:504] [C1] read ready
[2020-01-13 23:21:31.587][32261][debug][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:191] [C1] handshake expecting read
[2020-01-13 23:21:31.587][32261][trace][connection] [source/common/network/connection_impl.cc:466] [C1] socket event: 3
[2020-01-13 23:21:31.587][32261][trace][connection] [source/common/network/connection_impl.cc:554] [C1] write ready
[2020-01-13 23:21:31.588][32261][debug][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:176] [C1] handshake complete
[2020-01-13 23:21:31.588][32261][debug][client] [source/common/http/codec_client.cc:72] [C1] connected
[2020-01-13 23:21:31.588][32261][debug][pool] [source/common/http/http2/conn_pool.cc:97] [C1] creating stream
[2020-01-13 23:21:31.588][32261][debug][router] [source/common/router/router.cc:1711] [C0][S11753050428919145210] pool ready
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: stream: adjusting kept idle streams num_idle_streams=0, max=100
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/codec_impl.cc:710] [C1] send data: bytes=24
[2020-01-13 23:21:31.588][32261][trace][connection] [source/common/network/connection_impl.cc:402] [C1] writing 24 bytes, end_stream false
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: stream: adjusting kept idle streams num_idle_streams=0, max=100
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: end transmission of client magic
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: reset nghttp2_active_outbound_item
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: aob->item = (nil)
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: next frame: payloadlen=12, type=4, flags=0x00, stream_id=0
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/codec_impl.cc:656] [C1] about to send frame type=4, flags=0
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: start transmitting frame type=4, length=21
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/codec_impl.cc:710] [C1] send data: bytes=21
[2020-01-13 23:21:31.588][32261][trace][connection] [source/common/network/connection_impl.cc:402] [C1] writing 21 bytes, end_stream false
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: stream: adjusting kept idle streams num_idle_streams=0, max=100
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: end transmission of a frame
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/codec_impl.cc:604] [C1] sent frame type=4
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: reset nghttp2_active_outbound_item
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: aob->item = 0x55930fa0a460
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: next frame: payloadlen=4, type=8, flags=0x00, stream_id=0
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/codec_impl.cc:656] [C1] about to send frame type=8, flags=0
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: start transmitting frame type=8, length=13
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/codec_impl.cc:710] [C1] send data: bytes=13
[2020-01-13 23:21:31.588][32261][trace][connection] [source/common/network/connection_impl.cc:402] [C1] writing 13 bytes, end_stream false
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: stream: adjusting kept idle streams num_idle_streams=0, max=100
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: end transmission of a frame
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/codec_impl.cc:604] [C1] sent frame type=8
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: reset nghttp2_active_outbound_item
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: aob->item = 0x55930fa0a500
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: stream: dep_add dep_stream(0x55930fc18020)=0, stream(0x55930fa125a0)=1
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: deflating :scheme: https
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: name/value match index=6
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: emit indexed index=6, 1 bytes
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: deflating :method: POST
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: name/value match index=2
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: emit indexed index=2, 1 bytes
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: deflating :authority: grpc-echo-oxouww7xzq-uc.a.run.app
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: name match index=0
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: emit indname index=0, valuelen=33, indexing_mode=0
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: emit string str=grpc-echo-oxouww7xzq-uc.a.run.app, length=33, huffman=1, encoded_length=25
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: deflating :path: /test.grpc.Test/Echo
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: name match index=3
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: emit indname index=3, valuelen=20, indexing_mode=1
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: emit string str=/test.grpc.Test/Echo, length=20, huffman=1, encoded_length=14
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: deflating te: trailers
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: emit newname namelen=2, valuelen=8, indexing_mode=0
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: emit string str=te, length=2, huffman=0, encoded_length=2
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: emit string str=trailers, length=8, huffman=1, encoded_length=6
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: deflating content-type: application/grpc
[2020-01-13 23:21:31.588][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: name match index=30
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: emit indname index=30, valuelen=16, indexing_mode=0
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: emit string str=application/grpc, length=16, huffman=1, encoded_length=11
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: deflating user-agent: grpc-c++/1.22.0-dev grpc-c/7.0.0 (linux; chttp2; gale)
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: name match index=57
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: emit indname index=57, valuelen=54, indexing_mode=0
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: emit string str=grpc-c++/1.22.0-dev grpc-c/7.0.0 (linux; chttp2; gale), length=54, huffman=1, encoded_length=42
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: deflating grpc-accept-encoding: identity,deflate,gzip
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: emit newname namelen=20, valuelen=21, indexing_mode=0
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: emit string str=grpc-accept-encoding, length=20, huffman=1, encoded_length=14
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: emit string str=identity,deflate,gzip, length=21, huffman=1, encoded_length=16
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: deflating accept-encoding: identity,gzip
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: name match index=15
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: emit indname index=15, valuelen=13, indexing_mode=0
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: emit string str=identity,gzip, length=13, huffman=1, encoded_length=10
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: deflating x-forwarded-proto: http
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: emit newname namelen=17, valuelen=4, indexing_mode=0
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: emit string str=x-forwarded-proto, length=17, huffman=1, encoded_length=13
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: emit string str=http, length=4, huffman=1, encoded_length=3
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: deflating x-request-id: 0275133f-c83b-47be-8b18-4cfa9c4d884a
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: emit newname namelen=12, valuelen=36, indexing_mode=0
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: emit string str=x-request-id, length=12, huffman=1, encoded_length=9
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: emit string str=0275133f-c83b-47be-8b18-4cfa9c4d884a, length=36, huffman=1, encoded_length=26
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: deflating x-envoy-expected-rq-timeout-ms: 15000
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: emit newname namelen=30, valuelen=5, indexing_mode=0
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: emit string str=x-envoy-expected-rq-timeout-ms, length=30, huffman=1, encoded_length=22
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: emit string str=15000, length=5, huffman=1, encoded_length=4
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: deflatehd: all input name/value pairs were deflated
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: HEADERS/PUSH_PROMISE, payloadlen=244
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: before padding, HEADERS serialized in 253 bytes
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: padding selected: payloadlen=244, padlen=0
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: padlen = 0, nothing to do
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: HEADERS finally serialized in 253 bytes
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: next frame: payloadlen=244, type=1, flags=0x04, stream_id=1
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/codec_impl.cc:656] [C1] about to send frame type=1, flags=4
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: start transmitting frame type=1, length=253
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/codec_impl.cc:710] [C1] send data: bytes=253
[2020-01-13 23:21:31.589][32261][trace][connection] [source/common/network/connection_impl.cc:402] [C1] writing 253 bytes, end_stream false
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: stream: adjusting kept idle streams num_idle_streams=0, max=100
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: end transmission of a frame
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/codec_impl.cc:604] [C1] sent frame type=1
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: stream: stream=1 attach item=0x55930fa0a500
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: stream: stream=1 obq push cycle=0
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: stream: push stream 1 to stream 0
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: reset nghttp2_active_outbound_item
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: aob->item = 0x55930fa0a320
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: remote windowsize connection=65535, remote maxframsize=16384, stream(id 1)=65535
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: available window=16384
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: DATA postponed due to Data transfer deferred
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: stream: stream=1 defer item=0x55930fa0a500 cause=08
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: stream: remove stream 1 from stream 0
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: reset nghttp2_active_outbound_item
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: aob->item = (nil)
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: frame transmission deferred
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: stream: stream=1 resume item=0x55930fa0a500 flags=08
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: stream: stream=1 obq push cycle=0
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: stream: push stream 1 to stream 0
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: stream: adjusting kept idle streams num_idle_streams=0, max=100
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: remote windowsize connection=65535, remote maxframsize=16384, stream(id 1)=65535
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: available window=16384
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: padlen = 0, nothing to do
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: stream: stream=1 obq resched cycle=320
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: next frame: DATA
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: no copy DATA
[2020-01-13 23:21:31.589][32261][trace][connection] [source/common/network/connection_impl.cc:402] [C1] writing 29 bytes, end_stream false
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: stream: stream=1 detach item=0x55930fa0a500
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: stream: remove stream 1 from stream 0
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/codec_impl.cc:604] [C1] sent frame type=0
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: reset nghttp2_active_outbound_item
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: aob->item = 0x55930fa0a500
[2020-01-13 23:21:31.589][32261][trace][connection] [source/common/network/connection_impl.cc:554] [C1] write ready
[2020-01-13 23:21:31.589][32261][trace][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:259] [C1] ssl write returns: 340
[2020-01-13 23:21:31.589][32261][trace][connection] [source/common/network/connection_impl.cc:504] [C1] read ready
[2020-01-13 23:21:31.589][32261][trace][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:80] [C1] ssl read returns: -1
[2020-01-13 23:21:31.589][32261][trace][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:155] [C1] ssl read 0 bytes into 0 slices
[2020-01-13 23:21:31.589][32261][trace][connection] [source/common/network/connection_impl.cc:466] [C1] socket event: 2
[2020-01-13 23:21:31.589][32261][trace][connection] [source/common/network/connection_impl.cc:554] [C1] write ready
[2020-01-13 23:21:31.589][32261][trace][connection] [source/common/network/connection_impl.cc:466] [C1] socket event: 3
[2020-01-13 23:21:31.589][32261][trace][connection] [source/common/network/connection_impl.cc:554] [C1] write ready
[2020-01-13 23:21:31.589][32261][trace][connection] [source/common/network/connection_impl.cc:504] [C1] read ready
[2020-01-13 23:21:31.589][32261][trace][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:80] [C1] ssl read returns: 1379
[2020-01-13 23:21:31.589][32261][trace][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:80] [C1] ssl read returns: 333
[2020-01-13 23:21:31.589][32261][trace][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:80] [C1] ssl read returns: 0
[2020-01-13 23:21:31.589][32261][debug][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:226] [C1] 
[2020-01-13 23:21:31.589][32261][trace][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:155] [C1] ssl read 1712 bytes into 1 slices
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/codec_impl.cc:405] [C1] dispatching 1712 bytes
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: recv: connection recv_window_size=0, local_window=268435456
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: stream: adjusting kept idle streams num_idle_streams=0, max=100
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: recv: [IB_READ_FIRST_SETTINGS]
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/codec_impl.cc:424] [C1] dispatched 1712 bytes
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: stream: adjusting kept idle streams num_idle_streams=0, max=100
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: next frame: payloadlen=25, type=7, flags=0x00, stream_id=0
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/codec_impl.cc:656] [C1] about to send frame type=7, flags=0
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: start transmitting frame type=7, length=34
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/codec_impl.cc:710] [C1] send data: bytes=34
[2020-01-13 23:21:31.589][32261][trace][connection] [source/common/network/connection_impl.cc:402] [C1] writing 34 bytes, end_stream false
[2020-01-13 23:21:31.589][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: stream: adjusting kept idle streams num_idle_streams=0, max=100
[2020-01-13 23:21:31.590][32261][trace][http2] [source/common/http/http2/nghttp2.cc:25] nghttp2: send: end transmission of a frame
[2020-01-13 23:21:31.590][32261][trace][http2] [source/common/http/http2/codec_impl.cc:604] [C1] sent frame type=7
[2020-01-13 23:21:31.590][32261][debug][http2] [source/common/http/http2/codec_impl.cc:607] [C1] sent goaway code=1
[2020-01-13 23:21:31.590][32261][debug][client] [source/common/http/codec_client.cc:127] [C1] protocol error: The user callback function failed
[2020-01-13 23:21:31.590][32261][debug][connection] [source/common/network/connection_impl.cc:101] [C1] closing data_to_write=34 type=1
[2020-01-13 23:21:31.590][32261][trace][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:259] [C1] ssl write returns: 34
[2020-01-13 23:21:31.590][32261][debug][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:298] [C1] SSL shutdown: rc=0
[2020-01-13 23:21:31.590][32261][debug][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:226] [C1] 
[2020-01-13 23:21:31.590][32261][debug][connection] [source/common/network/connection_impl.cc:192] [C1] closing socket: 1
[2020-01-13 23:21:31.590][32261][debug][client] [source/common/http/codec_client.cc:91] [C1] disconnect. resetting 1 pending requests
[2020-01-13 23:21:31.590][32261][debug][client] [source/common/http/codec_client.cc:114] [C1] request reset
[2020-01-13 23:21:31.590][32261][trace][main] [source/common/event/dispatcher_impl.cc:162] item added to deferred deletion list (size=1)
[2020-01-13 23:21:31.590][32261][debug][pool] [source/common/http/http2/conn_pool.cc:232] [C1] destroying stream: 0 remaining
[2020-01-13 23:21:31.590][32261][debug][router] [source/common/router/router.cc:990] [C0][S11753050428919145210] upstream reset: reset reason connection termination
[2020-01-13 23:21:31.591][32261][debug][http] [source/common/http/conn_manager_impl.cc:1406] [C0][S11753050428919145210] Sending local reply with details upstream_reset_before_response_started{connection termination}
[2020-01-13 23:21:31.591][32261][debug][http] [source/common/http/conn_manager_impl.cc:1604] [C0][S11753050428919145210] encoding headers via codec (end_stream=true):
':status', '200'
'content-type', 'application/grpc'
'grpc-status', '14'
'grpc-message', 'upstream connect error or disconnect/reset before headers. reset reason: connection termination'
'date', 'Mon, 13 Jan 2020 23:21:31 GMT'
'server', 'envoy'

@mattklein123
Copy link
Member

[2020-01-13 23:21:31.590][32261][debug][http2] [source/common/http/http2/codec_impl.cc:607] [C1] sent goaway code=1

Is indicating a protocol error:

/**
   * PROTOCOL_ERROR
   */
  NGHTTP2_PROTOCOL_ERROR = 0x01,

It's not clear from the logs what the issue is. Note that we have had issues in the past with gRPC's HTTP/2 implementation not being spec compliant.

@qiwzhang
Copy link
Contributor Author

@mattklein123 the second log has more nghttp2 traces. It may provide more insights

@mattklein123
Copy link
Member

I looked at the 2nd log. I don't see anything in there that identifies why nghttp2 is deciding there is a protocol error unfortunately.

@qiwzhang
Copy link
Contributor Author

Update.

Here is the data dump received from Cloud Run after sending Http2 header.

===
HTTP/1.0 400 Bad Request
Content-Type: text/html; charset=UTF-8
Referrer-Policy: no-referrer
Content-Length: 1555
Date: Tue, 14 Jan 2020 01:56:32 GMT

<title>Error 400 (Bad Request)!!1</title> <style> *{margin:0;padding:0}html,code{font:15px/22px arial,sans-serif}html{background:#fff;color:#222;padding:15px}body{margin:7% auto 0;max-width:390px;min-height:180px;padding:30px 0 15px}* > body{background:url(//www.google.com/images/errors/robot.png) 100% 5px no-repeat;padding-right:205px}p{margin:11px 0 22px;overflow:hidden}ins{color:#777;text-decoration:none}a img{border:0}@media screen and (max-width:772px){body{background:none;margin-top:0;max-width:none;padding-right:0}}#logo{background:url(//www.google.com/images/branding/googlelogo/1x/googlelogo_color_150x54dp.png) no-repeat;margin-left:-5px}@media only screen and (min-resolution:192dpi){#logo{background:url(//www.google.com/images/branding/googlelogo/2x/googlelogo_color_150x54dp.png) no-repeat 0% 0%/100% 100%;-moz-border-image:url(//www.google.com/images/branding/googlelogo/2x/googlelogo_color_150x54dp.png) 0}}@media only screen and (-webkit-min-device-pixel-ratio:2){#logo{background:url(//www.google.com/images/branding/googlelogo/2x/googlelogo_color_150x54dp.png) no-repeat;-webkit-background-size:100% 100%}}#logo{display:inline-block;height:54px;width:150px} </style>

400. That�s an error.

Your client has issued a malformed or illegal request. That�s all we know.

Cloud Run doesn't like the Http2 headers or gRPC headers Envoy is sending.

@JLXIA
Copy link

JLXIA commented Jan 14, 2020

some thoughts:

1, gRPC should be HTTP/2, not HTTP/1
2, gRPC Content-Type shouldn't be text/html

@htuch htuch added the investigate Potential bug that needs verification label Jan 14, 2020
@PiotrSikora
Copy link
Contributor

You're missing alpn_protocols: h2 in your cluster's TLS config, so HTTP/2 is never negotiated with the upstream.

@qiwzhang
Copy link
Contributor Author

@PiotrSikora Thanks. After add "alpn_protocols: h2", it works.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
investigate Potential bug that needs verification
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@PiotrSikora @mattklein123 @htuch @qiwzhang @JLXIA