elixir-ecto / db_connection

Database connection behaviour
http://hexdocs.pm/db_connection/DBConnection.html
309 stars 112 forks source link

`mix test` now shows `DBConnection.Ownership.Manager` debug logs constantly. #54

Closed ghost closed 8 years ago

ghost commented 8 years ago

I see in #50, you've added the logging. I am sure that is a good thing! However, now when I run my mix test, I get a ton of debug log messages:

[08:07:07.584 debug] line=202 module=DBConnection.Ownership.Manager function=owner_down/2 
#PID<0.2377.0>, #PID<0.2384.0>, #PID<0.2382.0>, #PID<0.2380.0>, #PID<0.1538.0> lose proxy #PID<0.2378.0>

Perhaps the compiled package on hex can exclude the debug level messages?

fishcakez commented 8 years ago

Hex fetches the source and compiles it locally. However we could have an option to disable the debug log messages though.

ghost commented 8 years ago

I was trying to find it, but I thought I had previously read guidance to set the debug log level to info when releasing packages on hex.

ghost commented 8 years ago

I also have to say that I disagree with the "enhancement" label. I'm not an elixir expert, but I don't have any issues with debug log messages with any other packages :-/

fishcakez commented 8 years ago

@josevalim what is the recommended path here?

fishcakez commented 8 years ago

@bill-mybiz the debug messages here are to help a user debug their own code, rather than to debug the pool. It can be very difficult to discover bugs in tests when a process gets the wrong connection.

ghost commented 8 years ago

@fishcakez I have no doubt that debug messages with the connection would be very useful in many circumstances. But, I also think that the following should not happen:

screenshot from 2016-08-18 08-34-28

I could completely capture all logging in tests, which I've seen others apparently do. But I use the test logs in lieu of a debugger usually, and that is an incredible amount of noise. And again, I state, that no other hex package I have includes this behavior.

ghost commented 8 years ago

Btw, that is only one screen. I have 6 (more) entire screens filled with just those log messages.

fishcakez commented 8 years ago

@bill-mybiz my comment was in reference to your suggestion to switch to info, instead of debug. I think debug is the correct level. Perhaps we can make it configurable.

I added the enhancement label so we can add an option to disable the debug logging. Ecto will log every query by default at the debug level unless disabled by configuration. We should allow this log to be configured too.

ghost commented 8 years ago

@fishcakez It's your package, and you are the master of your domain! And I know that I have enjoyed the debug-level QUERY log messages from ecto. But I am working at it from my end, which (In addition to a bug in ecto which forced me to roll back to v.2.0.2), was extremely jarring when I went from:

mix_test_green

to the above screenshots of pages upon pages of new, confusing, and quite unhelpful log messages. I suppose part of the issue is that it is executed before the @tag :capture_log takes effect?

And I apologize if I balk at the enhancement label - it is from my previous experiences with issues where teams simply ignore everything that isn't a bug, e.g. the infamous application output filtering which I am still a little sore about. But there is hope! I forget that the Elixir team has the hands-down best issue response that I've seen!

So if you think it's an enhancement and you're going to do something about that...that's awesome! But at the very least, you are now aware that people with test cases are going to see the newly included logging files messages quite a bit, even if they have @tag :capture_log on.

fishcakez commented 8 years ago

Wait, you see the debug logs even with @tag :capture_log?

ghost commented 8 years ago

I have already rolled it back, but yes. All of my 100+ tests have that tag on, and it was firing for each one. I could double-check if you'd like, but I'm about to eat some lunch.

fishcakez commented 8 years ago

@bill-mybiz ok, I guess we will turn it off by default then and add the option ownership_log: nil | Logger.level

josevalim commented 8 years ago

@bill-mybiz https://github.com/bill-mybiz ok, I guess we will turn it off by default then and add the option ownership_log: nil | Logger.level

That is my vote too! Thanks James!

José Valimwww.plataformatec.com.br http://www.plataformatec.com.br/Founder and Director of R&D

ghost commented 8 years ago

@fishcakez Ok, I'm looking forward to learning a new Logger concept!

(I have just cloned my ibgib repo and double-checked. Just running mix deps.update db_connection reproduced it.)

fishcakez commented 8 years ago

Fixed in 95e14fe.

josevalim commented 8 years ago

New release done!

ghost commented 8 years ago

I've updated and done another round of tests with the new release, and everything on my end is looking good.

Thanks @fishcakez and @josevalim!