gRPC-JSON Transcoder did not response with 504 when route timeout reached

[arifsetiawan]

Issue Template

Title: gRPC-JSON Transcoder did not response with 504 when route timeout reached

Description:

.proto

syntax = "proto3";

package helloworld;
import "annotations.proto";

// The greeting service definition.
service Greeter {
  // Sends a greeting
  rpc SayHello (HelloRequest) returns (HelloReply) {
    option (google.api.http) = {
      post: "/simple/v0.1.0/hello"
      body: "*"
    };
  }
}

// The request message containing the user's name.
message HelloRequest {
  string name = 1;
}

// The response message containing the greetings
message HelloReply {
  string message = 1;
}

Golang server

package main

import (
	"fmt"
	"log"
	"net"
	"time"

	pb "gitlab.com/artoz/grpc-go-simple/helloworld"
	"golang.org/x/net/context"
	"google.golang.org/grpc"
	"google.golang.org/grpc/codes"
	"google.golang.org/grpc/reflection"
	"google.golang.org/grpc/status"
)

const (
	port = ":50051"
)

// server is used to implement helloworld.GreeterServer.
type server struct{}

// SayHello implements helloworld.GreeterServer
func (s *server) SayHello(ctx context.Context, in *pb.HelloRequest) (*pb.HelloReply, error) {
	fmt.Println(time.Now().Format(time.RFC3339), "Incoming request", in)
	if in.Name == "timeout" {
                // sleep for some time because this is long process
		time.Sleep(90 * time.Second)
		fmt.Println(time.Now().Format(time.RFC3339), "Send response", codes.DeadlineExceeded)
		return nil, status.Error(codes.DeadlineExceeded, in.Name)
	}

	if in.Name == "internal" {
		fmt.Println(time.Now().Format(time.RFC3339), "Send response", codes.Internal)
		return nil, status.Error(codes.Internal, in.Name)
	}

	fmt.Println(time.Now().Format(time.RFC3339), "Send response", "Hello "+in.Name)
	return &pb.HelloReply{Message: "Hello " + in.Name}, nil
}

func main() {
	lis, err := net.Listen("tcp", port)
	if err != nil {
		log.Fatalf("failed to listen: %v", err)
	}
	s := grpc.NewServer()
	pb.RegisterGreeterServer(s, &server{})
	// Register reflection service on gRPC server.
	reflection.Register(s)
	if err := s.Serve(lis); err != nil {
		log.Fatalf("failed to serve: %v", err)
	}
}

Envoy version

envoy 0a355de4999ecf3d05c78857137ed5b04cef7f11/Clean/RELEASE live 343 343 0

Envoy config

{
    "listeners": [{
        "address": "tcp://0.0.0.0:80",
        "filters": [{
            "type": "read",
            "name": "http_connection_manager",
            "config": {
                "server_name": "nextapi",
                "codec_type": "auto",
                "stat_prefix": "ingress_http",
                "use_remote_address": true,
                "access_log": [{"path": "/tmp/envoy.access.log"}],
                "route_config": {
                    "virtual_hosts": [{
                        "name": "grpc_service",
                        "domains": ["*"],
                        "routes": [{
                            "prefix": "/",
                            "cluster": "grpc1",
                            "timeout_ms": 5000
                        }]
                    }]
                },
                "filters": [
                    {
                        "type": "both",
                        "name": "grpc_json_transcoder",
                        "config": {
                            "proto_descriptor": "/etc/helloworld.pb",
                            "services": ["helloworld.Greeter"],
                            "print_options": {
                                "add_whitespace": false,
                                "always_print_primitive_fields": false,
                                "always_print_enums_as_ints": false,
                                "preserve_proto_field_names": false
                            }
                        }
                    },    
                    {
                        "type": "decoder",
                        "name": "router",
                        "config": {}
                    },
                    {
                        "name": "cors",
                        "config": {}
                    }
                ]
            }
        }]
    }],
    "admin": {
        "access_log_path": "/tmp/admin_access.log",
        "address": "tcp://0.0.0.0:9901"
    },
    "cluster_manager": {
        "clusters": [{
            "name": "grpc1",
            "connect_timeout_ms": 250,
            "type": "static",
            "lb_type": "random",
            "features": "http2",
            "hosts": [
                {"url": "tcp://192.168.99.100:50051"} 
            ]
        }]
    }
}

If I tried with Node.js grpc client

var PROTO_PATH = __dirname + '/helloworld.proto';
var grpc = require('grpc');
var proto = grpc.load(PROTO_PATH).helloworld;

function main() {
  var client = new proto.Greeter('192.168.99.100:80',grpc.credentials.createInsecure());

  var hrstart = process.hrtime();
  client.sayHello({name: "timeout"},function(err, response) {
    if (err) {
        console.error(err)
    }

    hrend = process.hrtime(hrstart);
    console.info("Execution time (hr): %ds %dms", hrend[0], hrend[1]/1000000);
    console.log(response)
  });
}

main()

I will get following error message after several seconds

{ Error: Received http2 header with status: 504
    at /Users/arifsetiawan/Repository/Artoz/apiserver-envoy/client/node_modules/grpc/src/client.js:554:15 code: 1, metadata: Metadata { _internal_repr: {} } }
Execution time (hr): 7s 916.071999ms

I think is coming from Envoy because of route timeout setting.

If I use curl to access HTTP API, I expect HTTP API should also response with HTTP status 504. I found that I don't get error reply from server and connection keep open

curl -X POST http://192.168.99.100/simple/v0.1.0/hello -d '{"name":"timeout"}' -v
*   Trying 192.168.99.100...
* Connected to 192.168.99.100 (192.168.99.100) port 80 (#0)
> POST /simple/v0.1.0/hello HTTP/1.1
> Host: 192.168.99.100
> User-Agent: curl/7.43.0
> Accept: */*
> Content-Length: 18
> Content-Type: application/x-www-form-urlencoded
> 
* upload completely sent off: 18 out of 18 bytes
``

[mattklein123]

@lizan you mind taking a look at this when you have a few moments?

[lizan]

Thanks for reporting @arifsetiawan, I believe it is a bug in transcoder filter and I will fix it soon.