Tracing

[michaelst]

I'm looking to implement http request tracing in elixir (inspired by this in GO: https://pkg.go.dev/net/http/httptrace).

This is not ready but before investing more time in this I wanted to see what the thoughts are on this general direction for implementation and if this is something that would be welcome in mint. I was thinking the callback fun was the most flexible as others could hookup telemetry with that or send messages to a process where you need to tie the timings back to a specfic request, for example

{:ok, conn} =
  Mint.HTTP.connect(:https, "example.com", 443,
    log: true,
    trace_fun: fn event ->
      send(self, {:trace, event, System.monotonic_time()})
      :ok
    end
  )

However, if there are other alternatives I'm happy to shift direction as well. Mainly wanted to start the conversation for this.

[whatyouhide]

Mh. I understand the need for this but I’m a bit worried about having a custom way of tracing. An alternative would be to have telemetry: true | false and then emit Telemetry events instead, which is a very standard API in BEAM-land. @josevalim @ericmj thoughts?

[josevalim]

Mint is a low level library, so I think we would need to argue why the tracing needs to happen inside Mint and not done by whoever is calling Mint.

Telemetry has a cost and I know Finch already adds tracing, I would be wary of paying the price twice or more.

[whatyouhide]

There are some things that you cannot know that Mint is doing, like hostname resolution or HTTP/2 internals, so maybe it could make sense for that. We've been generally against this sort of tracing in the past because of what @josevalim said but yeah some stuff is not really "inspectable" right now...

[michaelst]

Currently there is no way to hook into the tcp connect, dns, and tls phases (if there is a way in Finch I will just pivot to that but I'm not seeing those events) which is why I was exploring this way of implementing. Also happy to explore the telemetry route, I think if it is an opt in setting like log there wouldn't be any overhead for anyone not explicitly trying to achieve this.

Ideally it would be nice not to have to create a whole separate http client specifically for this purpose and be able to build upon mint.

As a reference also see others wanting something like this https://elixirforum.com/t/how-to-trace-time-in-http-requests/16557

[josevalim]

I'd definitely prefer a custom function over telemetry. It would be nice if the function passed state around instead of relying on callbacks, but I don't know if Mint has a private field or something similar we could use to achieve this.

[whatyouhide]

I'd definitely prefer a custom function over telemetry.

Why? To keep it localized and not go through the global handlers ETS and stuff?

I don't know if Mint has a private field

It does, it does 😎

[josevalim]

Why? To keep it localized and not go through the global handlers ETS and stuff?

Exactly. Also, if the goal is to eventually include this in Erlang/OTP, we can't have telemetry there.

[whatyouhide]

if the goal is to eventually include this in Erlang/OTP, we can't have telemetry there.

Ah yeah fantastic catch. Ok, then let's go with a function!

It would be nice if the function passed state around instead of relying on callbacks

What did you mean here? An idea for an API would be:

Mint.HTTP.connect(
  ...,
  trace_state: :whatever,
  trace_fun: fn state, event ->
    ...
    state
  end
)

[josevalim]

yeah, perhaps passing the mint socket itself as argument

[michaelst]

A couple of questions to clarify to help me finish this work.

The mint socket is created in the initiate function of each protocol, which is called after transport.connect. So currently we would not have access to that during these tracing function calls. We could move the mint socket up into HTTP1.connect and HTTP2.connect call and pass that through instead of all of the individual pieces (scheme, hostname, port, etc).

For trace_state is the intention that whatever trace_fun returns updates trace_state? Would we store that in :private assuming we move the mint socket up a level.

As for events I'm thinking these are most valuable initially [:connect_done, :dns_done, :tls_done, :first_byte_received, :request_done]. Any others that would be worth adding and are we good with the naming on those?

[whatyouhide]

A good callout is that passing the conn around without being able to update it is mostly something to read the conn. In that case, maybe it would be enough for users to just pass the conn as the initial trace state if they wish so. Thoughts?

[michaelst]

Sorry if I’m missing something but the conn is returned by connect so it wouldn’t be available yet to pass in as state by the user

[josevalim]

Could you prebuild the conn with initial information? and then just set the remaining fields after you connect?

[josevalim]

If that's too complicated, you can also just pass the private field.

[michaelst]

I think prebuilding the conn does make sense and pass it through and then later update with the tcp/ssl socket once we have it. Sounds like we also want a trace_state option and I'm guessing put that in private and then make the function definition this

@type tracing_event :: [:dns_done, :connect_done, :tls_done, :first_byte_received, :request_done]

Mint.HTTP.connect(
  ...,
  trace_state: :whatever, # gets put in private.trace_state
  # @spec trace_fun(Mint.t(), tracing_event()) :: any() 
  trace_fun: fn conn, event ->
    ...
  end
)

[josevalim]

I would make it a tuple trace_fun: {:state, fn ...}.

[michaelst]

I implemented what was discussed for http2, how do we feel about this implementation? If everyone is good with this I will finish up everything and get all tests passing.

[whatyouhide]

Hi @michaelst, any reason for closing this?

[michaelst]

Was waiting on feedback before continuing