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

Add telemetry events to handlers #25

Closed
wants to merge 6 commits into from
Closed

Add telemetry events to handlers #25

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
b2afaec
Add telemetry events
bryannaegele Feb 29, 2020
661248c
PR feedback
bryannaegele Mar 4, 2020
3452b5c
WG Feedback
bryannaegele Apr 9, 2020
da57bfb
Change event name and move success to else
bryannaegele Apr 9, 2020
b1bb2df
formatting
bryannaegele Apr 9, 2020
b64e364
failure -> exception
bryannaegele Apr 9, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
22 changes: 20 additions & 2 deletions lib/plug/cowboy/handler.ex
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,13 @@ defmodule Plug.Cowboy.Handler do
@already_sent {:plug_conn, :sent}

def init(req, {plug, opts}) do
start = System.monotonic_time()

:telemetry.execute([:plug_adapter, :request, :start], %{
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

tbh, I don't really understand the event name. I don't see the concept :request really in this library. Plug has an adapter concept, but nothing is explicitly called plug_adapter. Maybe [:plug, :adapter, :handler, :start]?

If I had my way, I'd go with [:plug_cowboy, :handler, :start] since that's a pretty literal mapping of the code that's being executed.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The question is if a handler is a requirement of plug_adapter or just an implementation naming thing here in this library. It would just need to be consistent across adapters. Does anyone know the details?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🤷 As long as it's a static name, I'll live with it

name: :plug_cowboy,
Copy link
Contributor

@binaryseed binaryseed Apr 13, 2020 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It looks like for this execute, name is in the measurements, but for the other one, name is in the metadata. Shouldn't it always be in the metadata?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Also, the conn that is created just below this has important information in it (like the path). I think we should probably include conn in the metadata for the start event

start_time: System.system_time()
})

conn = @connection.conn(req)

try do
Expand All @@ -15,13 +22,24 @@ defmodule Plug.Cowboy.Handler do
{:ok, req, {plug, opts}}
catch
kind, reason ->
exit_on_error(kind, reason, System.stacktrace(), {plug, :call, [conn, opts]})
stacktrace = System.stacktrace()
metadata = %{kind: kind, error: reason, stacktrace: stacktrace, name: :plug_cowboy}
measurements = %{duration: System.monotonic_time() - start}
:telemetry.execute([:plug_adapter, :request, :exception], measurements, metadata)

exit_on_error(kind, reason, stacktrace, {plug, :call, [conn, opts]})
after
receive do
@already_sent -> :ok
after
0 -> :ok
0 ->
:ok
end
else
result ->
measurements = %{duration: System.monotonic_time() - start}
:telemetry.execute([:plug_adapter, :request, :stop], measurements, %{name: :plug_cowboy})
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ideally we'd have the updated conn in this event... This is how I did the :stop event in my PR:

https://github.com/elixir-plug/plug_cowboy/pull/27/files#diff-497f9396e978da4bf4bfa189df9f6f13R19-R29

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Did you see the discussion at #25 (comment)? I'm happy to add it back.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I mean, w/o the conn I'd say this instrumentation is pretty pointless. There'd be no way to aggregate on anything, so we'd just literally get measurements like average request time for every request.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Let's add the connection to all events then (and in this case it is result). I also propose to rename name: :plug_cowboy to adapter: :plug_cowboy. Thoughts?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is the updated conn part of the result? It looks like only req is extracted & returned

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

A problem I ran into in my PR is that there's no way that I could figure out to get ahold of an updated conn in the case of an exception being raised.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Let’s return the conn then from try. There is nothing we can do about catch though, it is a non local return.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is the issue I ran into with the Tesla PR where you may want to know something about the conn in an exception. If you reference it from there it is the original argument.

Let’s return the conn then from try.

What is the suggestion here? I'm a little confused.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it's to assign the result of maybe_send inside the try block & call :telemetry.execute there...

https://github.com/elixir-plug/plug_cowboy/pull/27/files#diff-497f9396e978da4bf4bfa189df9f6f13R19-R28

result
end
end

Expand Down
1 change: 1 addition & 0 deletions mix.exs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -34,6 +34,7 @@ defmodule Plug.Cowboy.MixProject do
[
{:plug, "~> 1.7"},
{:cowboy, "~> 2.5"},
{:telemetry, "~> 0.4"},
{:ex_doc, "~> 0.20", only: :docs},
{:hackney, "~> 1.2.0", only: :test},
{:kadabra, "0.3.4", only: :test},
Expand Down
1 change: 1 addition & 0 deletions mix.lock
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,5 +15,6 @@
"plug_crypto": {:hex, :plug_crypto, "1.0.0", "18e49317d3fa343f24620ed22795ec29d4a5e602d52d1513ccea0b07d8ea7d4d", [:mix], [], "hexpm"},
"ranch": {:hex, :ranch, "1.6.2", "6db93c78f411ee033dbb18ba8234c5574883acb9a75af0fb90a9b82ea46afa00", [:rebar3], [], "hexpm"},
"ssl_verify_hostname": {:hex, :ssl_verify_hostname, "1.0.6", "45866d958d9ae51cfe8fef0050ab8054d25cba23ace43b88046092aa2c714645", [:make], [], "hexpm"},
"telemetry": {:hex, :telemetry, "0.4.1", "ae2718484892448a24470e6aa341bc847c3277bfb8d4e9289f7474d752c09c7f", [:rebar3], [], "hexpm"},
"x509": {:hex, :x509, "0.6.0", "51a274a8368cf6fe771c1920ce5b075d28a076745987666593adb818aadf1bf7", [:mix], [], "hexpm"},
}