Add telemetry events to handlers #25

bryannaegele · 2020-02-29T18:30:03Z

@josevalim can you verify this handles the stop and failure as we intend?

lib/plug/cowboy/handler.ex

bryannaegele · 2020-03-04T15:21:28Z

If we aren't going to automatically add the module name in the meta, I tend to agree with this. That said, it may be possible to get the module through discovery. There could be pitfalls, but for tracing purposes, I think it might be fine since the events should be unique.

…

On Wed, Mar 4, 2020, 8:03 AM Greg Mefford ***@***.***> wrote: ***@***.**** commented on this pull request. ------------------------------ In lib/plug/cowboy/handler.ex <#25 (comment)> : > @@ -4,6 +4,9 @@ defmodule Plug.Cowboy.Handler do @already_sent {:plug_conn, :sent} def init(req, {plug, opts}) do + start = System.monotonic_time() + :telemetry.execute([:plug_cowboy, :handler, :start], %{start_time: System.system_time()}) I don't mean to hold up this PR unnecessarily - I think we've just hit a "naming things is hard" situation. 😆 Ultimately, the maintainers of plug_cowboy can call their Telemetry events whatever they want. I personally don't see any reason not to call it [:plug_cowboy, :handler, :start] since that's a pretty straightforward description of where it's happening (as it is in the original PR). If folks want to call it something else or come up with some other standard naming convention for all such similar adapters, don't let me stand in the way. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#25?email_source=notifications&email_token=ABLXHVJLRILVB67MI2QH5T3RFZUT3A5CNFSM4K64XI7KYY3PNVWWK3TUL52HS4DFWFIHK3DMKJSXC5LFON2FEZLWNFSXPKTDN5WW2ZLOORPWSZGOCX6D6GI#discussion_r387723937>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ABLXHVIICR3WJJFTPP2JA2TRFZUT3ANCNFSM4K64XI7A> .

GregMefford · 2020-03-17T14:13:00Z

Just following up again on this PR because if we won't have something like my PR to Phoenix.Endpoint, then we should get this one released instead. Remaining issues I see:

failure -> exception
plug_cowboy.handler -> plug_adapter.request (I still don't really understand why this is better, but it's up to the maintainers)
If we go with plug_adapter.request, then the metadata should show which adapter it was, and somehow document this structure so that other plug_adapter implementers could know what the expected metadata is.

GregMefford · 2020-03-17T14:19:04Z

Oh! I was re-reading José's comment about item 2, that Phoenix has its own version of this handler and that's why we want to make it generic. I was thinking that plug_cowboy was directly used by Phoenix.

Now that I understand, I feel even more strongly that the right path is to just call it what it is: this one is plug_cowboy.* and that one is phoenix.*, so that it's obvious to people where it's coming from. No one will be confused when they switch from Plug to Phoenix or vice-versa and their metrics/traces don't look the same. That's a completely different tech stack even if they look similar, so if you want things to keep working, you'll need to reconfigure what you're tracing or include a different dependency that makes it work properly OoTB for you.

lib/plug/cowboy/handler.ex

bryannaegele · 2020-04-09T16:48:43Z

Is everyone OK with the event name and metadata structuring?

@GregMefford @binaryseed

lib/plug/cowboy/handler.ex

binaryseed · 2020-04-09T16:59:46Z

lib/plug/cowboy/handler.ex

+    else
+      result ->
+        measurements = %{duration: System.monotonic_time() - start}
+        :telemetry.execute([:plug_adapter, :request, :stop], measurements, %{name: :plug_cowboy})


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

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

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.

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?

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

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.

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

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.

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

binaryseed · 2020-04-09T17:05:30Z

lib/plug/cowboy/handler.ex

@@ -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], %{


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.

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?

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

binaryseed · 2020-04-09T18:20:49Z

I think a test would make sense, here's how I wired up one:

https://github.com/elixir-plug/plug_cowboy/pull/27/files#diff-217f2ca48d3f3e0b4b33f6dea78aeb10

GregMefford · 2020-04-10T00:45:28Z

Is there a matching PR for this in Phoenix? I just want to make sure we don’t have some blocker there that means we can’t have consistency, given that there’s a lot of assumptions or intentions to have this be consistent with the equivalent adapter that Phoenix uses.

binaryseed · 2020-04-13T17:40:21Z

lib/plug/cowboy/handler.ex

+    start = System.monotonic_time()
+
+    :telemetry.execute([:plug_adapter, :request, :start], %{
+      name: :plug_cowboy,


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?

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

Gazler · 2020-04-25T07:43:19Z

I believe this is closed by #31 - feel free to reopen it if I am mistaken though.

Add telemetry events

b2afaec

josevalim reviewed Feb 29, 2020

View reviewed changes