envoy: Transcoder triggers EOF with HTTP/2 when request body is "google.api.HttpBody"

Title: [gRPC-JSON transcoder] request field “google.api.HttpBody” triggers EOF if payload is less than 0x4000 bytes

Description:

What issue is being seen? Describe what should be happening instead of the bug, for example: Envoy should not crash, the expected value isn’t returned, etc.

I am currently running Istio (v10.0.0) on GKE (v1.19.9-gke.1400) which deploys Envoy (v1.18.3) as sidecar.

My application requires the gRPC-JSON transcoder in order to work but I am currently experiencing an unexpected behavior with a request that has google.api.HttpBody in the request field.

The google.api.HttpBody is correctly filled with data and content-type only in the following occasions:

• data is empty
• data is over 0x4000 bytes long

---

So we have the following weird behaviour of the gRPC-JSON transcoder with google.api.HttpBody request field:

• OK: 0 bytes
• EOF: 1 - 16384 bytes
• OK: 16385+ bytes

---

NOTE: I have tried to send the request directly to the Istio control plane, bypassing the Kubernetes ingress and Google Load Balancer to make sure they were not interfering with the request. The result was exactly the same as described.

When a request is sent with a payload that is less than 0x4000 bytes I receive the following error triggered by the upstream:

{
  "code": 2,
  "message": "EOF",
  "details": []
}

I deployed tcpdump to my cluster and analyzed the traffic with Wireshark and I can confirm that the error is triggered by the upstream service and that the data is missing in the gRPC request transcoded from the original raw request.

Insomnia request trace

> POST <redacted> HTTP/2
> Host: <redacted>
> user-agent: insomnia/2021.3.0
> content-type: application/custom
> authorization: Basic <redacted>
> accept: */*
> content-length: 3

| asd

* We are completely uploaded and fine
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* old SSL session ID is stale, removing
* Connection state changed (MAX_CONCURRENT_STREAMS == 100)!

< HTTP/2 500 
< content-type: application/json
< x-envoy-upstream-service-time: 2
< content-length: 50
< date: Sun, 23 May 2021 10:38:07 GMT
< server: istio-envoy
< via: 1.1 google
< alt-svc: clear

Wireshark packet dumps (envoy <-> downstream):

Frame 86: 2629 bytes on wire (21032 bits), 2629 bytes captured (21032 bits) on interface 0
Ethernet II, Src: ce:78:42:91:a7:46 (ce:78:42:91:a7:46), Dst: 62:63:85:be:d1:53 (62:63:85:be:d1:53)
Internet Protocol Version 4, Src: 10.64.16.89, Dst: 10.64.16.105
Transmission Control Protocol, Src Port: 36972, Dst Port: 9080, Seq: 1, Ack: 1, Len: 2563
HyperText Transfer Protocol 2
    Stream: Magic
        Magic: PRI * HTTP/2.0\r\n\r\nSM\r\n\r\n
    Stream: SETTINGS, Stream ID: 0, Length 30
        Length: 30
        Type: SETTINGS (4)
        Flags: 0x00
        0... .... .... .... .... .... .... .... = Reserved: 0x0
        .000 0000 0000 0000 0000 0000 0000 0000 = Stream Identifier: 0
        Settings - Enable PUSH : 0
        Settings - Header table size : 4096
        Settings - Unknown (8) : 0
        Settings - Max concurrent streams : 1073741824
        Settings - Initial Windows size : 268435456
    Stream: WINDOW_UPDATE, Stream ID: 0, Length 4
        Length: 4
        Type: WINDOW_UPDATE (8)
        Flags: 0x00
        0... .... .... .... .... .... .... .... = Reserved: 0x0
        .000 0000 0000 0000 0000 0000 0000 0000 = Stream Identifier: 0
        0... .... .... .... .... .... .... .... = Reserved: 0x0
        .000 1111 1111 1111 0000 0000 0000 0001 = Window Size Increment: 268369921
    Stream: HEADERS, Stream ID: 1, Length 2466, POST <redacted>
        Length: 2466
        Type: HEADERS (1)
        Flags: 0x04
        0... .... .... .... .... .... .... .... = Reserved: 0x0
        .000 0000 0000 0000 0000 0000 0000 0001 = Stream Identifier: 1
        [Pad Length: 0]
        Header Block Fragment: 8387418c9ed8d71d46a4a3acc85e42f7049c63b84745738c...
        [Header Length: 3336]
        [Header Count: 23]
        Header: :method: POST
        Header: :scheme: https
        Header: :authority: <redacted>
        Header: :path: <redacted>
        Header: user-agent: insomnia/2021.3.0
        Header: content-type: application/custom
        Header: accept: */*
        Header: content-length: 3
        Header: x-cloud-trace-context: 4f015190e41c055ba52de6038ae1e9df/17782916748087909721
        Header: x-client-data: CgSL6ZsV
        Header: via: 1.1 google
        Header: x-forwarded-for: <redacted>
        Header: x-forwarded-proto: https
        Header: x-envoy-external-address: 93.34.239.213
        Header: x-request-id: bd1be7dd-8c50-9cdc-9521-b20b9ed03450
        Header: x-envoy-decorator-operation: hub.apis.svc.cluster.local:9080/*
        Header: x-envoy-peer-metadata: <redacted>
        Header: x-envoy-peer-metadata-id: router~10.64.16.89~ingressgateway-external-68b84d8467-99zmt.istio-system~istio-system.svc.cluster.local
        Header: authorization: Bearer <redacted>
        Header: x-envoy-attempt-count: 1
        Header: x-datadog-trace-id: 1470028535987168232
        Header: x-datadog-parent-id: 1470028535987168232
        Header: x-datadog-sampling-priority: 1
    Stream: DATA, Stream ID: 1, Length 3
        Length: 3
        Type: DATA (0)
        Flags: 0x01
        0... .... .... .... .... .... .... .... = Reserved: 0x0
        .000 0000 0000 0000 0000 0000 0000 0001 = Stream Identifier: 1
        [Pad Length: 0]
        Data: 617364

Frame 88: 121 bytes on wire (968 bits), 121 bytes captured (968 bits) on interface 0
Ethernet II, Src: 62:63:85:be:d1:53 (62:63:85:be:d1:53), Dst: ce:78:42:91:a7:46 (ce:78:42:91:a7:46)
Internet Protocol Version 4, Src: 10.64.16.105, Dst: 10.64.16.89
Transmission Control Protocol, Src Port: 9080, Dst Port: 36972, Seq: 1, Ack: 2564, Len: 55
HyperText Transfer Protocol 2
    Stream: SETTINGS, Stream ID: 0, Length 24
        Length: 24
        Type: SETTINGS (4)
        Flags: 0x00
        0... .... .... .... .... .... .... .... = Reserved: 0x0
        .000 0000 0000 0000 0000 0000 0000 0000 = Stream Identifier: 0
        Settings - Header table size : 4096
        Settings - Unknown (8) : 0
        Settings - Max concurrent streams : 2147483647
        Settings - Initial Windows size : 268435456
    Stream: SETTINGS, Stream ID: 0, Length 0
        Length: 0
        Type: SETTINGS (4)
        Flags: 0x01
        0... .... .... .... .... .... .... .... = Reserved: 0x0
        .000 0000 0000 0000 0000 0000 0000 0000 = Stream Identifier: 0
    Stream: WINDOW_UPDATE, Stream ID: 0, Length 4
        Length: 4
        Type: WINDOW_UPDATE (8)
        Flags: 0x00
        0... .... .... .... .... .... .... .... = Reserved: 0x0
        .000 0000 0000 0000 0000 0000 0000 0000 = Stream Identifier: 0
        0... .... .... .... .... .... .... .... = Reserved: 0x0
        .000 1111 1111 1111 0000 0000 0000 0001 = Window Size Increment: 268369921

Frame 90: 75 bytes on wire (600 bits), 75 bytes captured (600 bits) on interface 0
Ethernet II, Src: ce:78:42:91:a7:46 (ce:78:42:91:a7:46), Dst: 62:63:85:be:d1:53 (62:63:85:be:d1:53)
Internet Protocol Version 4, Src: 10.64.16.89, Dst: 10.64.16.105
Transmission Control Protocol, Src Port: 36972, Dst Port: 9080, Seq: 2564, Ack: 56, Len: 9
HyperText Transfer Protocol 2
    Stream: SETTINGS, Stream ID: 0, Length 0
        Length: 0
        Type: SETTINGS (4)
        Flags: 0x01
        0... .... .... .... .... .... .... .... = Reserved: 0x0
        .000 0000 0000 0000 0000 0000 0000 0000 = Stream Identifier: 0

Frame 92: 1408 bytes on wire (11264 bits), 1408 bytes captured (11264 bits) on interface 0
Ethernet II, Src: 62:63:85:be:d1:53 (62:63:85:be:d1:53), Dst: ce:78:42:91:a7:46 (ce:78:42:91:a7:46)
Internet Protocol Version 4, Src: 10.64.16.105, Dst: 10.64.16.89
Transmission Control Protocol, Src Port: 9080, Dst Port: 36972, Seq: 56, Ack: 2573, Len: 1342
HyperText Transfer Protocol 2
    Stream: HEADERS, Stream ID: 1, Length 1274, 500 Internal Server Error
        Length: 1274
        Type: HEADERS (1)
        Flags: 0x04
        0... .... .... .... .... .... .... .... = Reserved: 0x0
        .000 0000 0000 0000 0000 0000 0000 0001 = Stream Identifier: 1
        [Pad Length: 0]
        Header Block Fragment: 3fe11f8e5f8b1d75d0620d263d4c7441ea4095f2b16aee7f...
        [Header Length: 1677]
        [Header Count: 9]
        Header table size update
        Header: :status: 500 Internal Server Error
        Header: content-type: application/json
        Header: x-envoy-upstream-service-time: 1
        Header: content-length: 50
        Header: x-envoy-peer-metadata: <redacted>
        Header: x-envoy-peer-metadata-id: sidecar~10.64.16.105~hub-0.apis~apis.svc.cluster.local
        Header: date: Sun, 23 May 2021 11:14:40 GMT
        Header: server: istio-envoy
    Stream: DATA, Stream ID: 1, Length 50
        Length: 50
        Type: DATA (0)
        Flags: 0x01
        0... .... .... .... .... .... .... .... = Reserved: 0x0
        .000 0000 0000 0000 0000 0000 0000 0001 = Stream Identifier: 1
        [Pad Length: 0]
        Data: 7b0a2022636f6465223a20322c0a20226d65737361676522...
    JavaScript Object Notation: application/json
        Object
            Member Key: code
                Number value: 2
                Key: code
            Member Key: message
                String value: EOF
                Key: message
            Member Key: details
                Array
                Key: details

Wireshark packet dumps (envoy <-> upstream):

Frame 3161: 889 bytes on wire (7112 bits), 889 bytes captured (7112 bits) on interface 0
Ethernet II, Src: 00:00:00_00:00:00 (00:00:00:00:00:00), Dst: 00:00:00_00:00:00 (00:00:00:00:00:00)
Internet Protocol Version 4, Src: 127.0.0.6, Dst: 10.64.16.99
Transmission Control Protocol, Src Port: 55081, Dst Port: 9080, Seq: 274956, Ack: 373, Len: 823
HyperText Transfer Protocol 2
    Stream: HEADERS, Stream ID: 3, Length 805, POST /myapp.myservice.v1alpha1.MyService/MyMethod
        Length: 805
        Type: HEADERS (1)
        Flags: 0x04
        0... .... .... .... .... .... .... .... = Reserved: 0x0
        .000 0000 0000 0000 0000 0000 0000 0011 = Stream Identifier: 3
        [Pad Length: 0]
        Header Block Fragment: 8387cf049c60751a92a273d4bcf6c6bf708e8ae71857c464...
        [Header Length: 1606]
        [Header Count: 22]
        Header: :method: POST
        Header: :scheme: https
        Header: :authority: <redacted>
        Header: :path: /myapp.myservice.v1alpha1.MyService/MyMethod
        Header: user-agent: insomnia/2021.3.0
        Header: content-type: application/grpc
        Header: accept: */*
        Header: x-cloud-trace-context: 91c606318cb8e802fb4b3cd368ba5379/6422320425799053054
        Header: x-client-data: CgSM6ZsV
        Header: via: 1.1 google
        Header: x-forwarded-for: <redacted>
        Header: x-forwarded-proto: https
        Header: x-envoy-external-address: <redacted>
        Header: x-request-id: 4bb0901e-4829-9a1b-a2d3-7bbd716da18e
        Header: authorization: Bearer <redacted>
        Header: x-envoy-attempt-count: 1
        Header: x-envoy-original-path: <redacted>
        Header: x-envoy-original-method: POST
        Header: te: trailers
        Header: x-datadog-trace-id: 1801031032039246500
        Header: x-datadog-parent-id: 6731941596774806256
        Header: x-datadog-sampling-priority: 1
    Stream: DATA, Stream ID: 3, Length 0
        Length: 0
        Type: DATA (0)
        Flags: 0x01
            .... ...1 = End Stream: True
            .... 0... = Padded: False
            0000 .00. = Unused: 0x00
        0... .... .... .... .... .... .... .... = Reserved: 0x0
        .000 0000 0000 0000 0000 0000 0000 0011 = Stream Identifier: 3
        [Pad Length: 0]
        Data: <MISSING>

Frame 3163: 96 bytes on wire (768 bits), 96 bytes captured (768 bits) on interface 0
Ethernet II, Src: 00:00:00_00:00:00 (00:00:00:00:00:00), Dst: 00:00:00_00:00:00 (00:00:00:00:00:00)
Internet Protocol Version 4, Src: 10.64.16.99, Dst: 127.0.0.6
Transmission Control Protocol, Src Port: 9080, Dst Port: 55081, Seq: 373, Ack: 275779, Len: 30
HyperText Transfer Protocol 2
    Stream: WINDOW_UPDATE, Stream ID: 0, Length 4
        Length: 4
        Type: WINDOW_UPDATE (8)
        Flags: 0x00
            0000 0000 = Unused: 0x00
        0... .... .... .... .... .... .... .... = Reserved: 0x0
        .000 0000 0000 0000 0000 0000 0000 0000 = Stream Identifier: 0
        0... .... .... .... .... .... .... .... = Reserved: 0x0
        .000 0000 0000 0000 0010 1100 0110 1111 = Window Size Increment: 11375
    Stream: PING, Stream ID: 0, Length 8
        Length: 8
        Type: PING (6)
        Flags: 0x00
            .... ...0 = ACK: False
            0000 000. = Unused: 0x00
        0... .... .... .... .... .... .... .... = Reserved: 0x0
        .000 0000 0000 0000 0000 0000 0000 0000 = Stream Identifier: 0
        Ping: 02041010090e0707

Frame 3165: 87 bytes on wire (696 bits), 87 bytes captured (696 bits) on interface 0
Ethernet II, Src: 00:00:00_00:00:00 (00:00:00:00:00:00), Dst: 00:00:00_00:00:00 (00:00:00:00:00:00)
Internet Protocol Version 4, Src: 10.64.16.99, Dst: 127.0.0.6
Transmission Control Protocol, Src Port: 9080, Dst Port: 55081, Seq: 403, Ack: 275779, Len: 21
HyperText Transfer Protocol 2
    Stream: HEADERS, Stream ID: 3, Length 12, 200 OK
        Length: 12
        Type: HEADERS (1)
        Flags: 0x05
            .... ...1 = End Stream: True
            .... .1.. = End Headers: True
            .... 0... = Padded: False
            ..0. .... = Priority: False
            00.0 ..0. = Unused: 0x00
        0... .... .... .... .... .... .... .... = Reserved: 0x0
        .000 0000 0000 0000 0000 0000 0000 0011 = Stream Identifier: 3
        [Pad Length: 0]
        Header Block Fragment: 88c07f0001327f0003454f46
        [Header Length: 97]
        [Header Count: 4]
        Header: :status: 200 OK
        Header: content-type: application/grpc
        Header: grpc-status: 2
        Header: grpc-message: EOF

Frame 3167: 83 bytes on wire (664 bits), 83 bytes captured (664 bits) on interface 0
Ethernet II, Src: 00:00:00_00:00:00 (00:00:00:00:00:00), Dst: 00:00:00_00:00:00 (00:00:00:00:00:00)
Internet Protocol Version 4, Src: 127.0.0.6, Dst: 10.64.16.99
Transmission Control Protocol, Src Port: 55081, Dst Port: 9080, Seq: 275779, Ack: 424, Len: 17
HyperText Transfer Protocol 2
    Stream: PING, Stream ID: 0, Length 8
        Length: 8
        Type: PING (6)
        Flags: 0x01
            .... ...1 = ACK: True
            0000 000. = Unused: 0x00
        0... .... .... .... .... .... .... .... = Reserved: 0x0
        .000 0000 0000 0000 0000 0000 0000 0000 = Stream Identifier: 0
        Pong: 02041010090e0707

Notice

You can see that envoy is not sending any data to the upstream:

    Stream: DATA, Stream ID: 3, Length 0
        Length: 0
        Type: DATA (0)
        Flags: 0x01
            .... ...1 = End Stream: True
            .... 0... = Padded: False
            0000 .00. = Unused: 0x00
        0... .... .... .... .... .... .... .... = Reserved: 0x0
        .000 0000 0000 0000 0000 0000 0000 0011 = Stream Identifier: 3
        [Pad Length: 0]
        Data: <MISSING>

even though it received 3 bytes of payload from the downstream:

    Stream: DATA, Stream ID: 1, Length 3
        Length: 3
        Type: DATA (0)
        Flags: 0x01
        0... .... .... .... .... .... .... .... = Reserved: 0x0
        .000 0000 0000 0000 0000 0000 0000 0001 = Stream Identifier: 1
        [Pad Length: 0]
        Data: 617364

Repro steps:

Include sample requests, environment, etc. All data and inputs required to reproduce the bug.

The proto file looks like the following:

syntax = "proto3";

import "google/api/annotations.proto";
import "google/api/client.proto";
import "google/api/httpbody.proto";
import "google/protobuf/empty.proto";

package myapp.myservice.v1alpha1;

service MyService {
  rpc MyMethod(MyMethodRequest) returns (google.api.HttpBody) {
    option (google.api.http) = {
      post: "/v1alpha1/{name=*/*}"
      body: "http.body"
    };
  }
}

message MyMethodRequest {
  message Http {
    google.api.HttpBody body = 1;
  }

  string name = 1;
  Http http = 2;
}

Note: The Envoy_collect tool gathers a tarball with debug logs, config and the following admin endpoints: /stats, /clusters and /server_info. Please note if there are privacy concerns, sanitize the data prior to sharing the tarball/pasting.

Admin and Stats Output:

Include the admin output for the following endpoints: /stats, /clusters, /routes, /server_info. For more information, refer to the admin endpoint documentation.

Note: If there are privacy concerns, sanitize the data prior to sharing.

Config:

Include the config used to configure Envoy.

/usr/local/bin/envoy
concurrency: 2
configPath: ./etc/istio/proxy
controlPlaneAuthPolicy: MUTUAL_TLS
discoveryAddress: istiod.istio-system.svc:15012
drainDuration: 45s
gatewayTopology:
  numTrustedProxies: 2
parentShutdownDuration: 60s
proxyAdminPort: 15000
proxyMetadata:
  DD_ENV: development
  DD_VERSION: 1.10.0
serviceCluster: hub.apis
statNameLength: 189
statusPort: 15020
terminationDrainDuration: 5s
tracing:
  datadog:
    address: 192.168.1.36:8126
  sampling: 100

EnvoyFilter configuration for the transcoder:

apiVersion: networking.istio.io/v1alpha3
kind: EnvoyFilter
metadata:
  name: grpc-transcoder
  namespace: istio-system
spec:
  workloadSelector:
    labels:
      envoyfilters.istio.io/grpc-transcoder: enabled
  configPatches:
  - applyTo: HTTP_FILTER
    match:
      context: SIDECAR_INBOUND
      listener:
        filterChain:
          filter:
            name: envoy.filters.network.http_connection_manager
            subFilter:
              name: envoy.filters.http.router
        portNumber: 9080
    patch:
      operation: INSERT_BEFORE
      value:
        name: envoy.filters.http.grpc_json_transcoder
        typed_config:
          "@type": type.googleapis.com/envoy.extensions.filters.http.grpc_json_transcoder.v3.GrpcJsonTranscoder
          services:
          - myapp.myservice.v1alpha1.MyService
          print_options:
            add_whitespace: true
            always_print_enums_as_ints: false
            always_print_primitive_fields: true
            preserve_proto_field_names: false
          request_validation_options:
            reject_unknown_method: false
            reject_unknown_query_parameters: false
          convert_grpc_status: true
          proto_descriptor: /etc/envoy/proto.bin

Logs:

Include the access logs and the Envoy logs.

{
  "path": "<redacted>",
  "authority": "<redacted>",
  "upstream_host": "<redacted>",
  "requested_server_name": null,
  "duration": 1,
  "bytes_sent": 50,
  "upstream_cluster": "inbound|9080||",
  "x_forwarded_for": "<redacted>",
  "upstream_transport_failure_reason": null,
  "response_flags": "-",
  "response_code_details": "via_upstream",
  "bytes_received": 3,
  "connection_termination_details": null,
  "upstream_service_time": "0",
  "protocol": "HTTP/2",
  "request_id": "9195dbdd-53ad-912d-90a8-0c3a3c23acda",
  "upstream_local_address": "127.0.0.6:36997",
  "start_time": "2021-05-23T10:38:07.433Z",
  "downstream_remote_address": "<redacted>",
  "method": "POST",
  "response_code": 500,
  "downstream_local_address": "<redacted>",
  "route_name": "default",
  "user_agent": "insomnia/2021.3.0"
}

{"level":"debug","time":"2021-05-23T15:17:12.006398Z","scope":"envoy conn_handler","msg":"[C39] new connection"}
{"level":"debug","time":"2021-05-23T15:17:12.006920Z","scope":"envoy http2","msg":"[C39] updating connection-level initial window size to 268435456"}
{"level":"debug","time":"2021-05-23T15:17:12.007092Z","scope":"envoy http","msg":"[C39] new stream"}
{"level":"debug","time":"2021-05-23T15:17:12.007255Z","scope":"envoy http","msg":"[C39][S15240943017125303159] request headers complete (end_stream=false):\n':method', 'POST'\n':scheme', 'https'\n':authority', '<redacted>'\n':path', '/v1alpha1/mymethod'\n'user-agent', 'insomnia/2021.3.0'\n'content-type', 'application/custom'\n'accept', '*/*'\n'content-length', '3'\n'x-cloud-trace-context', '4a317e0fc840d2a43babe647d5bb00df/11289929872227975471'\n'via', '1.1 google'\n'x-forwarded-for', '<redacted>'\n'x-forwarded-proto', 'https'\n'x-envoy-external-address', '93.34.239.213'\n'x-request-id', '655bddcd-56a2-99f2-810b-fb1932fc0cc3'\n'x-envoy-decorator-operation', 'hub.apis.svc.cluster.local:9080/*'\n'x-envoy-peer-metadata', '<redacted>'\n'x-envoy-peer-metadata-id', 'router~10.64.16.117~ingressgateway-external-58f879b844-mmms8.istio-system~istio-system.svc.cluster.local'\n'x-envoy-attempt-count', '1'\n'x-datadog-trace-id', '5719053109614087554'\n'x-datadog-parent-id', '5719053109614087554'\n'x-datadog-sampling-priority', '1'\n"}
{"level":"debug","time":"2021-05-23T15:17:12.012333Z","scope":"envoy filter","msg":"AuthenticationFilter::decodeHeaders with config\npolicy {\n  peers {\n    mtls {\n      mode: PERMISSIVE\n    }\n  }\n}\nskip_validate_trust_domain: true\n"}
{"level":"debug","time":"2021-05-23T15:17:12.012512Z","scope":"envoy filter","msg":"[C39] validateX509 mode PERMISSIVE: ssl=false, has_user=false"}
{"level":"debug","time":"2021-05-23T15:17:12.012572Z","scope":"envoy filter","msg":"Payload has not peer authentication data"}
{"level":"debug","time":"2021-05-23T15:17:12.012595Z","scope":"envoy filter","msg":"Set principal from peer: "}
{"level":"debug","time":"2021-05-23T15:17:12.012612Z","scope":"envoy filter","msg":"Origin authenticator succeeded"}
{"level":"debug","time":"2021-05-23T15:17:12.012650Z","scope":"envoy filter","msg":"Saved Dynamic Metadata:\n"}
{"level":"debug","time":"2021-05-23T15:17:12.012859Z","scope":"envoy router","msg":"[C39][S15240943017125303159] cluster 'inbound|9080||' match for URL '/myapp.myservice.v1alpha1.MyService/MyMethod'"}
{"level":"debug","time":"2021-05-23T15:17:12.012964Z","scope":"envoy upstream","msg":"transport socket match, socket default selected for host with address 10.64.16.120:9080"}
{"level":"debug","time":"2021-05-23T15:17:12.013113Z","scope":"envoy upstream","msg":"Created host 10.64.16.120:9080."}
{"level":"debug","time":"2021-05-23T15:17:12.013253Z","scope":"envoy upstream","msg":"addHost() adding 10.64.16.120:9080"}
{"level":"debug","time":"2021-05-23T15:17:12.013333Z","scope":"envoy upstream","msg":"membership update for TLS cluster inbound|9080|| added 1 removed 0"}
{"level":"debug","time":"2021-05-23T15:17:12.013350Z","scope":"envoy upstream","msg":"re-creating local LB for TLS cluster inbound|9080||"}
{"level":"debug","time":"2021-05-23T15:17:12.013359Z","scope":"envoy upstream","msg":"membership update for TLS cluster inbound|9080|| added 1 removed 0"}
{"level":"debug","time":"2021-05-23T15:17:12.013368Z","scope":"envoy router","msg":"[C39][S15240943017125303159] router decoding headers:\n':method', 'POST'\n':scheme', 'https'\n':authority', '<redacted>'\n':path', '/myapp.myservice.v1alpha1.MyService/MyMethod'\n'user-agent', 'insomnia/2021.3.0'\n'content-type', 'application/grpc'\n'accept', '*/*'\n'x-cloud-trace-context', '4a317e0fc840d2a43babe647d5bb00df/11289929872227975471'\n'via', '1.1 google'\n'x-forwarded-for', '<redacted>'\n'x-forwarded-proto', 'https'\n'x-envoy-external-address', '93.34.239.213'\n'x-request-id', '655bddcd-56a2-99f2-810b-fb1932fc0cc3'\n'x-envoy-attempt-count', '1'\n'x-envoy-original-path', '/v1alpha1/mymethod'\n'x-envoy-original-method', 'POST'\n'te', 'trailers'\n'x-datadog-trace-id', '5719053109614087554'\n'x-datadog-parent-id', '5075026046853892548'\n'x-datadog-sampling-priority', '1'\n"}
{"level":"debug","time":"2021-05-23T15:17:12.013481Z","scope":"envoy pool","msg":"queueing stream due to no available connections"}
{"level":"debug","time":"2021-05-23T15:17:12.013550Z","scope":"envoy pool","msg":"trying to create new connection"}
{"level":"debug","time":"2021-05-23T15:17:12.013375Z","scope":"envoy upstream","msg":"re-creating local LB for TLS cluster inbound|9080||"}
{"level":"debug","time":"2021-05-23T15:17:12.013608Z","scope":"envoy pool","msg":"creating a new connection"}
{"level":"debug","time":"2021-05-23T15:17:12.013875Z","scope":"envoy client","msg":"[C40] connecting"}
{"response_flags":"-","response_code_details":"via_upstream","upstream_local_address":"127.0.0.6:39835","authority":"<redacted>","start_time":"2021-05-23T15:17:12.007Z","user_agent":"insomnia/2021.3.0","upstream_cluster":"inbound|9080||","bytes_received":3,"connection_termination_details":null,"method":"POST","upstream_service_time":"3","upstream_host":"10.64.16.120:9080","protocol":"HTTP/2","upstream_transport_failure_reason":null,"response_code":500,"downstream_local_address":"10.64.16.120:9080","requested_server_name":null,"downstream_remote_address":"130.211.3.155:0","x_forwarded_for":"<redacted>","bytes_sent":50,"route_name":"default","path":"/v1alpha1/mymethod","request_id":"655bddcd-56a2-99f2-810b-fb1932fc0cc3","duration":12}
{"level":"debug","time":"2021-05-23T15:17:12.015254Z","scope":"envoy connection","msg":"[C40] connecting to 10.64.16.120:9080"}
{"level":"debug","time":"2021-05-23T15:17:12.015386Z","scope":"envoy connection","msg":"[C40] connection in progress"}
{"level":"debug","time":"2021-05-23T15:17:12.015593Z","scope":"envoy http2","msg":"[C40] updating connection-level initial window size to 268435456"}
{"level":"debug","time":"2021-05-23T15:17:12.015658Z","scope":"envoy http","msg":"[C39][S15240943017125303159] request end stream"}
{"level":"debug","time":"2021-05-23T15:17:12.015779Z","scope":"envoy upstream","msg":"membership update for TLS cluster inbound|9080|| added 1 removed 0"}
{"level":"debug","time":"2021-05-23T15:17:12.015909Z","scope":"envoy upstream","msg":"re-creating local LB for TLS cluster inbound|9080||"}
{"level":"debug","time":"2021-05-23T15:17:12.015943Z","scope":"envoy connection","msg":"[C40] connected"}
{"level":"debug","time":"2021-05-23T15:17:12.015948Z","scope":"envoy client","msg":"[C40] connected"}
{"level":"debug","time":"2021-05-23T15:17:12.015957Z","scope":"envoy pool","msg":"[C40] attaching to next stream"}
{"level":"debug","time":"2021-05-23T15:17:12.015964Z","scope":"envoy pool","msg":"[C40] creating stream"}
{"level":"debug","time":"2021-05-23T15:17:12.016092Z","scope":"envoy router","msg":"[C39][S15240943017125303159] pool ready"}
{"level":"debug","time":"2021-05-23T15:17:12.019098Z","scope":"envoy client","msg":"[C40] response complete"}
{"level":"debug","time":"2021-05-23T15:17:12.019136Z","scope":"envoy pool","msg":"[C40] destroying stream: 0 remaining"}
{"level":"debug","time":"2021-05-23T15:17:12.019155Z","scope":"envoy router","msg":"[C39][S15240943017125303159] upstream headers complete: end_stream=true"}
{"level":"debug","time":"2021-05-23T15:17:12.019405Z","scope":"envoy http","msg":"[C39][S15240943017125303159] encoding headers via codec (end_stream=false):\n':status', '500'\n'content-type', 'application/json'\n'x-envoy-upstream-service-time', '3'\n'content-length', '50'\n'x-envoy-peer-metadata', '<redacted>'\n'x-envoy-peer-metadata-id', 'sidecar~10.64.16.120~hub-0.apis~apis.svc.cluster.local'\n'date', 'Sun, 23 May 2021 15:17:11 GMT'\n'server', 'istio-envoy'\n"}
{"level":"debug","time":"2021-05-23T15:17:12.019479Z","scope":"envoy http2","msg":"[C39] stream closed: 0"}