Optionally log last known call, publish stacktrace in telemetry

[v0idpwn]

Companion pr to elixir-ecto/ecto#3798

[tashirosota]

@v0idpwn
I'm curious, so I'd like to ask you a question.
Why that can fetch by Enum.at(stacktrace, 2)?
Stacktrace has many traces, in general, you want a match in the phx_app/lib/* and I think it's more useful.
How about fetch by match /:otp_app/lib path?
https://github.com/elixir-ecto/ecto_sql/pull/363/files#diff-9a458b905f34396e522038e878f83c957e4649c66a4a13f263bb8fcdcbbe744eR920
https://github.com/elixir-ecto/ecto_sql/pull/363/files#diff-9a458b905f34396e522038e878f83c957e4649c66a4a13f263bb8fcdcbbe744eR1042-R1070

[v0idpwn]

There's a trick here. I believe it works in 99% of the cases:

I changed the Process.info(self(), :current_stacktrace) up in the pipeline:
https://github.com/elixir-ecto/ecto/blob/a04b0de384dbf21b4440162f3a0165c8d47e08bc/lib/ecto/repo.ex#L260

The usual path is something around:
Your code -> Your Repo -> Ecto.Repo -> Ecto internals -> Ecto adapter internals (+dbconnection, etc)

When getting the stacktrace at the ecto adapters, it would have a lot of random things.
But getting it in Ecto.Repo, what I see is usually:

{Process, :info, 2, .....}
{Ecto.Repo, :repo_function_called, ....}
{MyApp.Repo, :repo_function_called, ....}
{Calling code, .........}

As I strip the process.info from the stacktrace (not really useful :)), your code is usually at position 2.

The only situation I can see it not behaving this way is if you're using some library that increases indirection between Ecto and your code. None comes to mind. But maybe it is worth, yes, to go safer and do something like that.

[v0idpwn]

I'm thinking of maybe getting alwaays the one below {MyApp.Repo, ...} instead of using numbers, which is kinda naive. But having some kind of configurability, as you did, may be the best... got to think about it

[josevalim]

We should do a Enum.drop instead and send the whole stacktrace. Let the entity who is logging figure out what to do with it.

[v0idpwn]

I'm not sure if I get you. I'm doing this here (ecto):

• https://github.com/elixir-ecto/ecto/blob/a04b0de384dbf21b4440162f3a0165c8d47e08bc/lib/ecto/repo.ex#L269
  And then filtering for log in the function that we are commenting on. Do you think we should log the whole stacktrace instead of first non-ecto?

[tashirosota]

Is this hint？ActiveSupport::BacktraceCleaner

[tashirosota]

@v0idpwn
Hi！Happy new year！
I created stacktrace_cleaner.
Can you use it?

[v0idpwn]

Hey, @tashirosota, sorry for not answering earlier :), happy new year!!

I totally agree that Enum.at(stacktrace, 2) is a problem, but I also don't want to tie it to path on Ecto itself. I've been thinking about it last few days, and probably the approach we will go with is:

1. Find the last ecto module in stacktrace
2. Return the next item

This is a bit naive, but should work for the general case. If this proves not to be enough, I'd be happy to add some interface where the user can plug their own stacktrace cleaner (it should be trivial to use your library to do it). But I think we probably shouldn't add more mandatory dependencies on Ecto.

[tashirosota]

@v0idpwn

1. Find the last ecto module in stacktrace, 2. Return the next item

It's so simply！sounds good！

But I think we probably shouldn't add more mandatory dependencies on Ecto.

OK！I learned this time. Thank you!
Will I close PR？

[v0idpwn]

I think yes, on favor of this one :). I will finish it this week and hopely we can merge it for next ecto release.

Thank you, you've been very helpful

[v0idpwn]

Just pushed a commit that gets the first non-ecto entry. Is there anything else that should be done before merge? 🙂

[josevalim]

Do Enum.drop_while it doesn't start with "Elixir.Ecto". Then check if it is an empty list, if not, it is the first element.

[v0idpwn]

Can't do it this way because we may have something like Enum in the middle (its the case for Ecto.Multi)

[josevalim]

I can be any operation from Enum. The point is that we should be able to traverse once instead of doing it twice. :)

[josevalim]

Just this comment and we are good to go. Ping me if you are not sure how to go ahead!

[v0idpwn]

I got a very simple solution with recursion. But I want to experiment a last bit more today :)

[josevalim]

Instead of find_index maybe find_value? Drop_while would also work :)

[josevalim]

There is a function called Exception.format_mfa or similar. :)

[tashirosota]

Sorry I'm late.
LGTM!!

[josevalim]

💚 💙 💜 💛 ❤️