beam-telemetry / cowboy_telemetry Goto Github PK

View Code? Open in Web Editor NEW

29.0 3.0 9.0 22 KB

Telemetry instrumentation for Cowboy

License: Apache License 2.0

Erlang 100.00%

cowboy_telemetry's Introduction

cowboy_telemetry

Telemetry instrumentation for the Cowboy HTTP server.

This package contains a cowboy_stream handler that will instrument each request and emit telemetry events.

Usage

Configure your cowboy server with the cowboy_telemetry_h stream handler first.

cowboy:start_clear(http, [{port, Port}], #{
    env => #{dispatch => Dispatch},
    stream_handlers => [cowboy_telemetry_h, cowboy_stream_h]
}.

Telemetry Events

`[cowboy, request, start]`

A span event emitted at the beginning of a request.

measurements: #{system_time => erlang:system_time()}
metadata: #{stream_id => cowboy_stream:streamid(), req => cowboy_req:req()}

`[cowboy, request, stop]`

A span event emitted at the end of a request.

measurements: measurements()
metadata: metadata()

If the request is terminated early - by the client or by the server - before a response is sent, the metadata will also contain an error:

metadata: metadata() + #{error => cowboy_stream:reason()}

`[cowboy, request, exception]`

A span event emitted if the request process exits.

measurements: measurements()
metadata: metadata() + #{kind => exit, stacktrace => list()}

`[cowboy, request, early_error]`

A single event emitted when Cowboy itself returns an early_error response before executing any handlers.

measurements: #{system_time => erlang:system_time(), resp_body_length => non_neg_integer()}
metadata: metadata() without procs or informational

Types

measurements():
- duration :: req_start - req_end see cowboy_metrics_h
- req_body_duration :: req_body_start - req_body_end see cowboy_metrics_h
- resp_duration :: resp_start - resp_end see cowboy_metrics_h
- req_body_length :: non_neg_integer()
- resp_body_length :: non_neg_integer()
metadata():
- pid, streamid, req, resp_headers, resp_status, ref and user_data from cowboy_metrics_h:metrics()
cowboy_metrics_h:metrics(): Defined in cowboy_metrics_h

Note:

The telemetry handlers are executed from the cowboy connection process, not from the request process.

cowboy_telemetry's People

Contributors

Stargazers

Watchers

Forkers

ioolkos starbelly wojtekmach hrzndhrn inkwell-data nkmanolovsumup preveil ikavgo bryannaegele

cowboy_telemetry's Issues

dependencies too strict causing issues

I think we might want to loosen up the dependencies like other libs

Failed to use "telemetry" (versions 0.4.0 to 0.4.2) because
  db_connection (version 2.4.1) requires ~> 0.4 or ~> 1.0
  deps/absinthe/mix.exs requires ~> 0.4.0
  ecto (version 3.7.1) requires ~> 0.4 or ~> 1.0
  ecto_sql (version 3.7.1) requires ~> 0.4.0 or ~> 1.0
  new_relic_agent (version 1.27.6) requires ~> 0.4 or ~> 1.0
  phoenix (version 1.5.13) requires ~> 0.4 or ~> 1.0
  phoenix_live_view (version 0.17.3) requires ~> 0.4.2 or ~> 1.0
  plug (version 1.12.1) requires ~> 0.4.3 or ~> 1.0
  redix (version 1.1.4) requires ~> 0.4.0 or ~> 1.0
  telemetry_metrics (version 0.6.1) requires ~> 0.4 or ~> 1.0


Failed to use "telemetry" (version 0.4.3) because
  cowboy_telemetry (version 0.4.0) requires ~> 1.0
  db_connection (version 2.4.1) requires ~> 0.4 or ~> 1.0
  deps/absinthe/mix.exs requires ~> 0.4.0
  ecto (version 3.7.1) requires ~> 0.4 or ~> 1.0
  ecto_sql (version 3.7.1) requires ~> 0.4.0 or ~> 1.0
  new_relic_agent (version 1.27.6) requires ~> 0.4 or ~> 1.0
  phoenix (version 1.5.13) requires ~> 0.4 or ~> 1.0
  phoenix_live_view (version 0.17.3) requires ~> 0.4.2 or ~> 1.0
  plug (version 1.12.1) requires ~> 0.4.3 or ~> 1.0
  redix (version 1.1.4) requires ~> 0.4.0 or ~> 1.0
  telemetry_metrics (version 0.6.1) requires ~> 0.4 or ~> 1.0

Missing commands

I've done a quick review of the handler. I see that you want to get start/end times for producing responses, but you're not handling all cases where a response ends here:

https://github.com/beam-telemetry/cowboy_telemetry/blob/main/src/cowboy_telemetry_h.erl#L28

In the case of Websocket the response will end on a 101 inform command.

When the headers command is used, the body is streamed, and the body is fully sent once the data command is used with fin as the second element of the tuple OR when the trailers frame is sent.

The internal_error will also result in a response being sent, if one was not sent already, but only for HTTP/1.1. In that case a 500 is sent. In HTTP/2's case a stream error will be sent.

If you can decouple tracing and metrics handling I would strongly suggest using cowboy_metrics_h for the metrics as you'll get a lot of useful information from there.

attach spans to the request span

The REAME says:

The telemetry handlers are executed from the cowboy connection process, not from the request process.

That mean the request process has no access to the span context. How am I then supposed to add subspans to the request span?

Write documentation

Relax dependency on Telemetry

Would it be possible to relax the dependency on telemetry?
Right now the dependency is marked as (~> 1.0), however seeing the changelog on telemetry there are no changes between 0.4.3 and 1.0.0, so in order to make upgrades easier it would be nice if the requirements for this library admitted also 0.4.3.
I can open a PR if we're good with that.

Cowboy Handler opentelemetry_cowboy_handlers has failed and has been detached when using rebar3 release command

Hello everyone,
I had encounter problem about Open Telemetry for Cowboy Erlang will detach
Handler opentelemetry_cowboy_handlers has failed and has been detached. Class=error
when I compile Cowboy project by using command like rebar3 as prod release then I start Erlang binary by using /path/to/erlang-release [foreground/console] but if I start project with rebar3 shell I will not encounter Handler Detach problem.
Everything working fine if using rebar3 shell

I'm assume that may be I set dependency incorrect ? but after I inspect file path it seem like I already have it and I can run project with rebar3 shell without any problem.

Run Erlang Project by using /path/to/erlang-release [foreground/console] will have error logs like this

Erlang/OTP 24 [erts-12.1.5] [source] [64-bit] [smp:16:16] [ds:16:16:10] [async-threads:1] [jit] [dtrace]

=======Before==============start_link=======Eshell V12.1.5  (abort with ^G)
(dockerwatch@cloudnative)1> *SPANS FOR DEBUG*
=ERROR REPORT==== 17-Dec-2021::10:31:29.735444 ===
Handler opentelemetry_cowboy_handlers has failed and has been detached. Class=error
Reason=undef
Stacktrace=[{otel_telemetry,start_telemetry_span,
                [opentelemetry_cowboy,<<"HTTP GET">>,
                 #{req =>
                       #{body_length => 0,cert => undefined,has_body => false,
                         headers =>
                             #{<<"accept">> =>
                                   <<"text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9">>,
                               <<"accept-encoding">> =>
                                   <<"gzip, deflate, br">>,
                               <<"accept-language">> => <<"en-US,en;q=0.9">>,
                               <<"connection">> => <<"keep-alive">>,
                               <<"cookie">> =>
                                   <<"s_fid=737CE1562D9C2574-0BD2980522487B59; _ga=GA1.1.154107132.1625138202; ai_user=3BShZm2OqNNQggPlYdNDXo|2021-08-23T08:23:54.731Z; MicrosoftApplicationsTelemetryDeviceId=e81308c7-b4d5-4479-9b90-6a7cc10880a8; MSFPC=GUID=f0b25916852047deb2fcd15c12d84da6&HASH=f0b2&LV=202106&V=4&LU=1622518798816; django_language=en; optimizely-user-id=3yvznvqrba.9; AMCV_D10F27705ED7F5130A495C99%40AdobeOrg=359503849%7CMCMID%7C21585024227443696071629298091785840441%7CMCAAMLH-1630552041%7C3%7CMCAAMB-1630552041%7CRKhpRz8krg2tLO6pguXWp5olkAcUniQYPHaMWWgdJ3xzPWQmdj0y%7CMCOPTOUT-1629954441s%7CNONE%7CvVersion%7C5.0.1; OPTOUTMULTI=0:0%7Cc1:1%7Cc2:0%7Cc3:0; utag_main=v_id:017b7d1689740004500708d7b69100087000c07f00781$_sn:3$_se:5$_ss:0$_st:1629953950624$is_country_requiring_explicit_consent:false$dc_visit:3$ses_id:1629952150171%3Bexp-session$_pn:1%3Bexp-session$dc_event:1%3Bexp-session$mm_sync:1%3Bexp-session$mm_ga_sync:1%3Bexp-session$dc_region:ap-east-1%3Bexp-session; _mkto_trk=id:157-GQE-382&token:_mch--1629707035373-12244; ajs_anonymous_id=63beef76-095f-4e7b-b106-cc406694c7d0">>,
                               <<"host">> => <<"localhost:8083">>,
                               <<"purpose">> => <<"prefetch">>,
                               <<"sec-ch-ua">> =>
                                   <<"\" Not A;Brand\";v=\"99\", \"Chromium\";v=\"96\", \"Google Chrome\";v=\"96\"">>,
                               <<"sec-ch-ua-mobile">> => <<"?0">>,
                               <<"sec-ch-ua-platform">> => <<"\"macOS\"">>,
                               <<"sec-fetch-dest">> => <<"document">>,
                               <<"sec-fetch-mode">> => <<"navigate">>,
                               <<"sec-fetch-site">> => <<"none">>,
                               <<"sec-fetch-user">> => <<"?1">>,
                               <<"upgrade-insecure-requests">> => <<"1">>,
                               <<"user-agent">> =>
                                   <<"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.93 Safari/537.36">>},
                         host => <<"localhost">>,method => <<"GET">>,
                         path => <<"/">>,
                         peer => {{127,0,0,1},62613},
                         pid => <0.626.0>,port => 8083,qs => <<>>,ref => http,
                         scheme => <<"http">>,
                         sock => {{127,0,0,1},8083},
                         streamid => 1,version => 'HTTP/1.1'},
                   streamid => 1},
                 #{}],
                []},
            {opentelemetry_cowboy,handle_event,4,
                [{file,
                     "/Users/yyyy/ProjectCode/yyy/yyyy-opentracing-demo/tracing-tracking-service/dockerwatch/_build/default/lib/opentelemetry_cowboy/src/opentelemetry_cowboy.erl"},
                 {line,49}]},
            {telemetry,'-execute/3-fun-0-',4,
                [{file,
                     "/Users/yyyy/ProjectCode/yyy/yyyy-opentracing-demo/tracing-tracking-service/dockerwatch/_build/default/lib/telemetry/src/telemetry.erl"},
                 {line,150}]},
            {lists,foreach,2,[{file,"lists.erl"},{line,1342}]},
            {cowboy_telemetry_h,init,3,
                [{file,
                     "/Users/yyyy/ProjectCode/yyy/yyyy-opentracing-demo/tracing-tracking-service/dockerwatch/src/cowboy_telemetry_h.erl"},
                 {line,11}]},
            {cowboy_stream,init,3,
                [{file,
                     "/Users/yyyy/ProjectCode/yyy/yyyy-opentracing-demo/tracing-tracking-service/dockerwatch/_build/default/lib/cowboy/src/cowboy_stream.erl"},
                 {line,112}]},
            {cowboy_http,after_parse,1,
                [{file,
                     "/Users/yyyy/ProjectCode/yyy/yyyy-opentracing-demo/tracing-tracking-service/dockerwatch/_build/default/lib/cowboy/src/cowboy_http.erl"},
                 {line,352}]},
            {proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,226}]}]

*SPANS FOR DEBUG*

Project Setup
I'm copy whole file of cowboy_telemetry_h.erl from your github repository then put in to my handler is it correct ?
Also opentelemetry_cowboy:setup() is using before Supervisor had been start like in my picture.

Thank you so much for helping !

wrong event ordering when used with HTTP/2

I'm not totally sure whether this is a bug in cowboy_telemetry or in the way the telemetry events are use by opentelemetry_cowboy.

telemetry:execute seems to have the assumption the all events send from a process belong to the same request or span.

The way cowboy handles HTTP/2 and invokes it stream handlers results in a violation of that assumption.

cowboy uses a single process for each TCP connection. All stream handlers will be invoked from that process. However, a single HTTP/2 connection can have multiple HTTP/2 streams. That means that events from different HTTP/2 requests can all be invoked from the same process. Requests on different HTTP/2 streams are not synchronized. That can result in interleaving calls to telemetry:execute.

The interleaving might not be a problem for metrics. But when the requests are used to start and stop tracing spans with only the information from the process itself, this will go wrong.

adding cowboy_metrics_h after cowboy_telemetry_h causes crash

Setting up the cowboy stream handler like this:

#{metrics_callback => fun prometheus_cowboy2_instrumenter:observe/1,
   stream_handlers => [cowboy_telemetry_h, cowboy_metrics_h, cowboy_stream_h]

leads to a crash:

2024-03-25T12:25:21.637585+01:00 <0.3469.0> telemetry:execute/3 : error: Handler opentelemetry_cowboy_handlers has failed and has been detached. Class=error
Reason={case_clause,[]}
Stacktrace=[{otel_telemetry,pop_from_tracer_stack,1,
                [{file,
                     "/usr/src/erlang/erccn/_build/default/lib/opentelemetry_telemetry/src/otel_telemetry.erl"},
                 {line,110}]},
            {otel_telemetry,end_telemetry_span,2,
                [{file,
                     "/usr/src/erlang/erccn/_build/default/lib/opentelemetry_telemetry/src/otel_telemetry.erl"},
                 {line,49}]},
            {opentelemetry_cowboy,handle_event,4,
                [{file,
                     "/usr/src/erlang/erccn/_build/default/lib/opentelemetry_cowboy/src/opentelemetry_cowboy.erl"},
                 {line,79}]},
            {telemetry,'-execute/3-fun-0-',4,
                [{file,
                     "/usr/src/erlang/erccn/_build/default/lib/telemetry/src/telemetry.erl"},
                 {line,160}]},
            {lists,foreach_1,2,[{file,"lists.erl"},{line,1686}]},
            {cowboy_metrics_h,terminate,3,
                [{file,
                     "/usr/src/erlang/erccn/_build/default/lib/cowboy/src/cowboy_metrics_h.erl"},
                 {line,302}]},
            {cowboy_stream,terminate,3,
                [{file,
                     "/usr/src/erlang/erccn/_build/default/lib/cowboy/src/cowboy_stream.erl"},
                 {line,138}]},
            {cowboy_http2,terminate_stream_handler,4,
                [{file,
                     "/usr/src/erlang/erccn/_build/default/lib/cowboy/src/cowboy_http2.erl"},
                 {line,1334}]}]

the problem is that cowboy_telemetry_h abuses cowboy_metrics_h and overwrites the metrics_callback setting.

A workarround is to change the order of the handlers:

#{metrics_callback => fun prometheus_cowboy2_instrumenter:observe/1,
   stream_handlers => [cowboy_metrics_h, cowboy_telemetry_h, cowboy_stream_h]

beam-telemetry / cowboy_telemetry Goto Github PK

cowboy_telemetry's Introduction

cowboy_telemetry

Usage

Telemetry Events

[cowboy, request, start]

[cowboy, request, stop]

[cowboy, request, exception]

[cowboy, request, early_error]