Handle error status returns instead of timing out

[tsloughter]

Currently the client will end up timing out when at least some error status codes are returned by the server instead of returning those errors.

@ferd do you have the erlang traces still that show this happening?

[ferd]

I've recreated these by sending in invalid content-types from the grpc client, and then tracing things to honeycomb.

1> recon_trace:calls([{grpcbox_client, '_', fun(_) -> return_trace() end}, {grpcbox_client_stream, '_', fun(_) -> return_trace() end}, {h2_connection, new_streaam, fun(_) -> return_trace() end}], 1000, [{scope, local}]).
36

9:4:57.485377 <0.867.0> grpcbox_client:unary({ctx,#{md_outgoing_key =>
           #{<<"x-honeycomb-dataset">> => <<"experiments">>,
             <<"x-honeycomb-team">> => <<"***">>}},
     undefined}, <<"/opentelemetry.proto.collector.trace.v1.TraceService/Export">>, #{resource_spans=>[#{instrumentation_library_spans => [],
   resource =>
       #{attributes =>
             [#{key => <<"service.name">>,
                value => #{value => {string_value,<<"unknown_service:erl">>}}},
              #{key => <<"process.runtime.version">>,
                value => #{value => {string_value,<<"11.1.8">>}}},
              #{key => <<"process.runtime.name">>,
                value => #{value => {string_value,<<"BEAM">>}}},
              #{key => <<"process.runtime.description">>,
                value =>
                    #{value =>
                          {string_value,<<"Erlang/OTP 24 erts-11.1.8">>}}},
              #{key => <<"process.executable.name">>,
                value => #{value => {string_value,<<"erl">>}}}],
         dropped_attributes_count => 0}}]}, {grpcbox_def,'opentelemetry.proto.collector.trace.v1.TraceService',
             <<"opentelemetry.proto.collector.trace.v1.ExportTraceServiceRequest">>,
             #Fun<opentelemetry_trace_service.0.8483745>,
             #Fun<opentelemetry_trace_service.1.8483745>}, #{channel=>opentelemetry_exporter})

9:4:57.498667 <0.867.0> grpcbox_client:get_channel(#{channel=>opentelemetry_exporter}, unary)

9:4:57.498786 <0.867.0> grpcbox_client:get_channel/2 --> {ok,{<0.833.0>,undefined}}

9:4:57.498867 <0.867.0> grpcbox_client:'-unary/5-fun-0-'({ctx,#{md_outgoing_key =>
           #{<<"x-honeycomb-dataset">> => <<"experiments">>,
             <<"x-honeycomb-team">> => <<"***">>}},
     undefined}, #{resource_spans=>[#{instrumentation_library_spans => [],
   resource =>
       #{attributes =>
             [#{key => <<"service.name">>,
                value => #{value => {string_value,<<"unknown_service:erl">>}}},
              #{key => <<"process.runtime.version">>,
                value => #{value => {string_value,<<"11.1.8">>}}},
              #{key => <<"process.runtime.name">>,
                value => #{value => {string_value,<<"BEAM">>}}},
              #{key => <<"process.runtime.description">>,
                value =>
                    #{value =>
                          {string_value,<<"Erlang/OTP 24 erts-11.1.8">>}}},
              #{key => <<"process.executable.name">>,
                value => #{value => {string_value,<<"erl">>}}}],
         dropped_attributes_count => 0}}]}, <<"/opentelemetry.proto.collector.trace.v1.TraceService/Export">>, {grpcbox_def,'opentelemetry.proto.collector.trace.v1.TraceService',
             <<"opentelemetry.proto.collector.trace.v1.ExportTraceServiceRequest">>,
             #Fun<opentelemetry_trace_service.0.8483745>,
             #Fun<opentelemetry_trace_service.1.8483745>}, #{channel=>opentelemetry_exporter}, <0.833.0>)

9:4:57.499315 <0.867.0> grpcbox_client:unary_handler({ctx,#{md_outgoing_key =>
           #{<<"x-honeycomb-dataset">> => <<"experiments">>,
             <<"x-honeycomb-team">> => <<"***">>}},
     undefined}, <0.833.0>, <<"/opentelemetry.proto.collector.trace.v1.TraceService/Export">>, #{resource_spans=>[#{instrumentation_library_spans => [],
   resource =>
       #{attributes =>
             [#{key => <<"service.name">>,
                value => #{value => {string_value,<<"unknown_service:erl">>}}},
              #{key => <<"process.runtime.version">>,
                value => #{value => {string_value,<<"11.1.8">>}}},
              #{key => <<"process.runtime.name">>,
                value => #{value => {string_value,<<"BEAM">>}}},
              #{key => <<"process.runtime.description">>,
                value =>
                    #{value =>
                          {string_value,<<"Erlang/OTP 24 erts-11.1.8">>}}},
              #{key => <<"process.executable.name">>,
                value => #{value => {string_value,<<"erl">>}}}],
         dropped_attributes_count => 0}}]}, {grpcbox_def,'opentelemetry.proto.collector.trace.v1.TraceService',
             <<"opentelemetry.proto.collector.trace.v1.ExportTraceServiceRequest">>,
             #Fun<opentelemetry_trace_service.0.8483745>,
             #Fun<opentelemetry_trace_service.1.8483745>}, #{channel=>opentelemetry_exporter})

9:4:57.499710 <0.867.0> grpcbox_client_stream:send_request({ctx,#{md_outgoing_key =>
           #{<<"x-honeycomb-dataset">> => <<"experiments">>,
             <<"x-honeycomb-team">> => <<"***">>}},
     undefined}, <0.833.0>, <<"/opentelemetry.proto.collector.trace.v1.TraceService/Export">>, #{resource_spans=>[#{instrumentation_library_spans => [],
   resource =>
       #{attributes =>
             [#{key => <<"service.name">>,
                value => #{value => {string_value,<<"unknown_service:erl">>}}},
              #{key => <<"process.runtime.version">>,
                value => #{value => {string_value,<<"11.1.8">>}}},
              #{key => <<"process.runtime.name">>,
                value => #{value => {string_value,<<"BEAM">>}}},
              #{key => <<"process.runtime.description">>,
                value =>
                    #{value =>
                          {string_value,<<"Erlang/OTP 24 erts-11.1.8">>}}},
              #{key => <<"process.executable.name">>,
                value => #{value => {string_value,<<"erl">>}}}],
         dropped_attributes_count => 0}}]}, {grpcbox_def,'opentelemetry.proto.collector.trace.v1.TraceService',
             <<"opentelemetry.proto.collector.trace.v1.ExportTraceServiceRequest">>,
             #Fun<opentelemetry_trace_service.0.8483745>,
             #Fun<opentelemetry_trace_service.1.8483745>}, #{channel=>opentelemetry_exporter})

9:4:57.500102 <0.867.0> grpcbox_client_stream:encoding_to_binary(identity)

9:4:57.500173 <0.867.0> grpcbox_client_stream:encoding_to_binary/1 --> <<"identity">>

9:4:57.500226 <0.867.0> grpcbox_client_stream:metadata_headers({ctx,#{md_outgoing_key =>
           #{<<"x-honeycomb-dataset">> => <<"experiments">>,
             <<"x-honeycomb-team">> => <<"***">>}},
     undefined})

9:4:57.500311 <0.867.0> grpcbox_client_stream:metadata_headers/1 --> [{<<"x-honeycomb-dataset">>,<<"experiments">>},
 {<<"x-honeycomb-team">>,<<"***">>}]

9:4:57.500492 <0.868.0> grpcbox_client_stream:init(<0.855.0>, 3, [{ssl,{sslsocket,{gen_tcp,#Port<0.18>,tls_connection,undefined},
                 [<0.860.0>,<0.859.0>]}},
 #{buffer => <<>>,client_pid => <0.867.0>,
   marshal_fun => #Fun<opentelemetry_trace_service.0.8483745>,
   path => <<"/opentelemetry.proto.collector.trace.v1.TraceService/Export">>,
   service => 'opentelemetry.proto.collector.trace.v1.TraceService',
   stats => #{},stats_handler => undefined,
   unmarshal_fun => #Fun<opentelemetry_trace_service.1.8483745>}])

9:4:57.500762 <0.868.0> grpcbox_client_stream:stats_handler({ctx,#{grpc_client_method =>
           <<"/opentelemetry.proto.collector.trace.v1.TraceService/Export">>},
     undefined}, rpc_begin, {}, #{buffer=><<>>, client_pid=><0.867.0>, marshal_fun=>#Fun<opentelemetry_trace_service.0.8483745>, path=><<"/opentelemetry.proto.collector.trace.v1.TraceService/Export">>, service=>'opentelemetry.proto.collector.trace.v1.TraceService', stats=>#{}, stats_handler=>undefined, unmarshal_fun=>#Fun<opentelemetry_trace_service.1.8483745>})

9:4:57.500959 <0.868.0> grpcbox_client_stream:stats_handler/4 --> #{buffer=><<>>, client_pid=><0.867.0>, ctx=>{ctx,#{grpc_client_method =>
           <<"/opentelemetry.proto.collector.trace.v1.TraceService/Export">>},
     undefined}, marshal_fun=>#Fun<opentelemetry_trace_service.0.8483745>, path=><<"/opentelemetry.proto.collector.trace.v1.TraceService/Export">>, service=>'opentelemetry.proto.collector.trace.v1.TraceService', stats=>#{}, stats_handler=>undefined, unmarshal_fun=>#Fun<opentelemetry_trace_service.1.8483745>}

9:4:57.501144 <0.868.0> grpcbox_client_stream:init/3 --> {ok,#{buffer => <<>>,client_pid => <0.867.0>,
      ctx =>
          {ctx,#{grpc_client_method =>
                     <<"/opentelemetry.proto.collector.trace.v1.TraceService/Export">>},
               undefined},
      marshal_fun => #Fun<opentelemetry_trace_service.0.8483745>,
      path =>
          <<"/opentelemetry.proto.collector.trace.v1.TraceService/Export">>,
      service => 'opentelemetry.proto.collector.trace.v1.TraceService',
      stats => #{},stats_handler => undefined,stream_id => 3,
      unmarshal_fun => #Fun<opentelemetry_trace_service.1.8483745>}}

9:4:57.501324 <0.867.0> grpcbox_client_stream:send_request/6 --> {ok,<0.855.0>,3,<0.868.0>}

9:4:57.501385 <0.867.0> grpcbox_client:recv_end(#{channel=><0.833.0>, monitor_ref=>#Ref<0.3440355339.2292449281.2520>, service_def=>{grpcbox_def,'opentelemetry.proto.collector.trace.v1.TraceService',
             <<"opentelemetry.proto.collector.trace.v1.ExportTraceServiceRequest">>,
             #Fun<opentelemetry_trace_service.0.8483745>,
             #Fun<opentelemetry_trace_service.1.8483745>}, stream_id=>3, stream_pid=><0.868.0>}, 5000)

9:4:57.521957 <0.868.0> grpcbox_client_stream:on_receive_headers([{<<":status">>,<<"464">>},
 {<<"server">>,<<"awselb/2.0">>},
 {<<"date">>,<<"Thu, 18 Mar 2021 13:04:57 GMT">>},
 {<<"content-length">>,<<"0">>}], #{buffer=><<>>, client_pid=><0.867.0>, ctx=>{ctx,#{grpc_client_method =>
           <<"/opentelemetry.proto.collector.trace.v1.TraceService/Export">>},
     undefined}, marshal_fun=>#Fun<opentelemetry_trace_service.0.8483745>, path=><<"/opentelemetry.proto.collector.trace.v1.TraceService/Export">>, service=>'opentelemetry.proto.collector.trace.v1.TraceService', stats=>#{}, stats_handler=>undefined, stream_id=>3, unmarshal_fun=>#Fun<opentelemetry_trace_service.1.8483745>})

9:4:57.522278 <0.868.0> grpcbox_client_stream:encoding_to_atom(identity)

9:4:57.522348 <0.868.0> grpcbox_client_stream:encoding_to_atom/1 --> identity

9:4:57.522404 <0.868.0> grpcbox_client_stream:on_receive_headers/2 --> {ok,#{buffer => <<>>,client_pid => <0.867.0>,
      ctx =>
          {ctx,#{grpc_client_method =>
                     <<"/opentelemetry.proto.collector.trace.v1.TraceService/Export">>},
               undefined},
      encoding => identity,
      marshal_fun => #Fun<opentelemetry_trace_service.0.8483745>,
      path =>
          <<"/opentelemetry.proto.collector.trace.v1.TraceService/Export">>,
      resp_headers =>
          [{<<":status">>,<<"464">>},
           {<<"server">>,<<"awselb/2.0">>},
           {<<"date">>,<<"Thu, 18 Mar 2021 13:04:57 GMT">>},
           {<<"content-length">>,<<"0">>}],
      service => 'opentelemetry.proto.collector.trace.v1.TraceService',
      stats => #{},stats_handler => undefined,stream_id => 3,
      unmarshal_fun => #Fun<opentelemetry_trace_service.1.8483745>}}

9:4:57.522642 <0.868.0> grpcbox_client_stream:on_end_stream(#{buffer=><<>>, client_pid=><0.867.0>, ctx=>{ctx,#{grpc_client_method =>
           <<"/opentelemetry.proto.collector.trace.v1.TraceService/Export">>},
     undefined}, encoding=>identity, marshal_fun=>#Fun<opentelemetry_trace_service.0.8483745>, path=><<"/opentelemetry.proto.collector.trace.v1.TraceService/Export">>, resp_headers=>[{<<":status">>,<<"464">>},
 {<<"server">>,<<"awselb/2.0">>},
 {<<"date">>,<<"Thu, 18 Mar 2021 13:04:57 GMT">>},
 {<<"content-length">>,<<"0">>}], service=>'opentelemetry.proto.collector.trace.v1.TraceService', stats=>#{}, stats_handler=>undefined, stream_id=>3, unmarshal_fun=>#Fun<opentelemetry_trace_service.1.8483745>})

9:4:57.522840 <0.868.0> grpcbox_client_stream:stats_handler({ctx,#{grpc_client_method =>
           <<"/opentelemetry.proto.collector.trace.v1.TraceService/Export">>},
     undefined}, rpc_end, {}, #{buffer=><<>>, client_pid=><0.867.0>, ctx=>{ctx,#{grpc_client_method =>
           <<"/opentelemetry.proto.collector.trace.v1.TraceService/Export">>},
     undefined}, encoding=>identity, marshal_fun=>#Fun<opentelemetry_trace_service.0.8483745>, path=><<"/opentelemetry.proto.collector.trace.v1.TraceService/Export">>, resp_headers=>[{<<":status">>,<<"464">>},
 {<<"server">>,<<"awselb/2.0">>},
 {<<"date">>,<<"Thu, 18 Mar 2021 13:04:57 GMT">>},
 {<<"content-length">>,<<"0">>}], service=>'opentelemetry.proto.collector.trace.v1.TraceService', stats=>#{}, stats_handler=>undefined, stream_id=>3, unmarshal_fun=>#Fun<opentelemetry_trace_service.1.8483745>})

9:4:57.523027 <0.868.0> grpcbox_client_stream:stats_handler/4 --> #{buffer=><<>>, client_pid=><0.867.0>, ctx=>{ctx,#{grpc_client_method =>
           <<"/opentelemetry.proto.collector.trace.v1.TraceService/Export">>},
     undefined}, encoding=>identity, marshal_fun=>#Fun<opentelemetry_trace_service.0.8483745>, path=><<"/opentelemetry.proto.collector.trace.v1.TraceService/Export">>, resp_headers=>[{<<":status">>,<<"464">>},
 {<<"server">>,<<"awselb/2.0">>},
 {<<"date">>,<<"Thu, 18 Mar 2021 13:04:57 GMT">>},
 {<<"content-length">>,<<"0">>}], service=>'opentelemetry.proto.collector.trace.v1.TraceService', stats=>#{}, stats_handler=>undefined, stream_id=>3, unmarshal_fun=>#Fun<opentelemetry_trace_service.1.8483745>}

9:4:57.523280 <0.868.0> grpcbox_client_stream:on_end_stream/1 --> {ok,#{buffer => <<>>,client_pid => <0.867.0>,
      ctx =>
          {ctx,#{grpc_client_method =>
                     <<"/opentelemetry.proto.collector.trace.v1.TraceService/Export">>},
               undefined},
      encoding => identity,
      marshal_fun => #Fun<opentelemetry_trace_service.0.8483745>,
      path =>
          <<"/opentelemetry.proto.collector.trace.v1.TraceService/Export">>,
      resp_headers =>
          [{<<":status">>,<<"464">>},
           {<<"server">>,<<"awselb/2.0">>},
           {<<"date">>,<<"Thu, 18 Mar 2021 13:04:57 GMT">>},
           {<<"content-length">>,<<"0">>}],
      service => 'opentelemetry.proto.collector.trace.v1.TraceService',
      stats => #{},stats_handler => undefined,stream_id => 3,
      unmarshal_fun => #Fun<opentelemetry_trace_service.1.8483745>}}

9:4:57.523519 <0.867.0> grpcbox_client:recv_end/2 --> eos

9:4:57.523577 <0.867.0> grpcbox_client:recv_headers(#{channel=><0.833.0>, monitor_ref=>#Ref<0.3440355339.2292449281.2520>, service_def=>{grpcbox_def,'opentelemetry.proto.collector.trace.v1.TraceService',
             <<"opentelemetry.proto.collector.trace.v1.ExportTraceServiceRequest">>,
             #Fun<opentelemetry_trace_service.0.8483745>,
             #Fun<opentelemetry_trace_service.1.8483745>}, stream_id=>3, stream_pid=><0.868.0>}, 0)

9:4:57.523692 <0.867.0> grpcbox_client:recv(headers, #{channel=><0.833.0>, monitor_ref=>#Ref<0.3440355339.2292449281.2520>, service_def=>{grpcbox_def,'opentelemetry.proto.collector.trace.v1.TraceService',
             <<"opentelemetry.proto.collector.trace.v1.ExportTraceServiceRequest">>,
             #Fun<opentelemetry_trace_service.0.8483745>,
             #Fun<opentelemetry_trace_service.1.8483745>}, stream_id=>3, stream_pid=><0.868.0>}, 0)

9:4:57.523824 <0.867.0> grpcbox_client:recv/3 --> {ok,#{<<":status">> => <<"464">>,<<"content-length">> => <<"0">>,
      <<"date">> => <<"Thu, 18 Mar 2021 13:04:57 GMT">>,
      <<"server">> => <<"awselb/2.0">>}}

9:4:57.523906 <0.867.0> grpcbox_client:recv_headers/2 --> {ok,#{<<":status">> => <<"464">>,<<"content-length">> => <<"0">>,
      <<"date">> => <<"Thu, 18 Mar 2021 13:04:57 GMT">>,
      <<"server">> => <<"awselb/2.0">>}}

9:4:57.523981 <0.867.0> grpcbox_client:recv_trailers(#{channel=><0.833.0>, monitor_ref=>#Ref<0.3440355339.2292449281.2520>, service_def=>{grpcbox_def,'opentelemetry.proto.collector.trace.v1.TraceService',
             <<"opentelemetry.proto.collector.trace.v1.ExportTraceServiceRequest">>,
             #Fun<opentelemetry_trace_service.0.8483745>,
             #Fun<opentelemetry_trace_service.1.8483745>}, stream_id=>3, stream_pid=><0.868.0>})

9:4:57.524077 <0.867.0> grpcbox_client:recv_trailers(#{channel=><0.833.0>, monitor_ref=>#Ref<0.3440355339.2292449281.2520>, service_def=>{grpcbox_def,'opentelemetry.proto.collector.trace.v1.TraceService',
             <<"opentelemetry.proto.collector.trace.v1.ExportTraceServiceRequest">>,
             #Fun<opentelemetry_trace_service.0.8483745>,
             #Fun<opentelemetry_trace_service.1.8483745>}, stream_id=>3, stream_pid=><0.868.0>}, 500)

9:4:57.524174 <0.867.0> grpcbox_client:recv(trailers, #{channel=><0.833.0>, monitor_ref=>#Ref<0.3440355339.2292449281.2520>, service_def=>{grpcbox_def,'opentelemetry.proto.collector.trace.v1.TraceService',
             <<"opentelemetry.proto.collector.trace.v1.ExportTraceServiceRequest">>,
             #Fun<opentelemetry_trace_service.0.8483745>,
             #Fun<opentelemetry_trace_service.1.8483745>}, stream_id=>3, stream_pid=><0.868.0>}, 500)

9:4:58.022737 <0.867.0> grpcbox_client:recv/3 --> timeout

9:4:58.023005 <0.867.0> grpcbox_client:recv_trailers/2 --> timeout

9:4:58.023263 <0.867.0> grpcbox_client:recv_trailers/1 --> timeout

Specifically the issue here is that the HTTP/2 stream got an HTTP/2 response (due to load balancer config erroring out on the bad content-type) rather than the full gRPC status-based mechanism, I imagine. This ended up confusing its handlers in not getting the payloads it expected.

I can generate traces of the h2_stream but the http2 client seems to be working fine and I assumed the narrower one on grpcbox + otel would be sufficient.

[tsloughter]

Yea, this is all I need. I'm simply having recv_headers check the status to make sure it is 200 and if not return an error instead of trying to receive the trailers.