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

Handle error status returns instead of timing out #54

Open
tsloughter opened this issue Mar 18, 2021 · 2 comments
Open

Handle error status returns instead of timing out #54

tsloughter opened this issue Mar 18, 2021 · 2 comments

Comments

@tsloughter
Copy link
Owner

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
Copy link

ferd commented Mar 18, 2021

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
Copy link
Owner Author

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.

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

No branches or pull requests
2 participants
@tsloughter @ferd