Refactored logging

[sdepold]

This PR changes the way sequelize logs SQL statements etc. Instead of always checking for options.logging, log statements are now just passed to sequelize.log. The following stuff is supported:

If options.logging is false => sequelize.log won't do anything.
If options.logging is a function which is not console.log => sequelize.log will pass the every but the first argument to the function.
If options.logging is console.log => use the winston logger and use the first argument as the event name (info, error, ...) and the other options as message(s). If only one argument is passed to sequelize.log use the info event.
If options.logging is an object => instantiate a winston logger with options.logging as options.

[mickhansen]

Why a hard dependency on winston?

[sdepold]

Dunno, Seems like a good choice ?

[sdepold]

would you prefer the previously implemented console.log as fallback? instead of winston?

[mickhansen]

Not sure, just seems weird to introduce a dependency, aren't there a few of logging libraries?

[durango]

Yeah I'd definitely separate out the functionality, keep console.log the default

[sdepold]

Alright. Logic is reverted to keep the previous behavior. @durango I wonder why anyone would need this https://github.com/sequelize/sequelize/blob/feature/logging/test/sequelize.test.js?pr=%2Fsequelize%2Fsequelize%2Fpull%2F1566#L627

If I get that one right, people are doing:

sequelize.sync({ force: true, logging: false })

Why would anyone enable logging, but enforce no logging for sync commands ?

[durango]

@sdepold at the time (this may still be true), even if I disabled logs through the options... .sync() would still emit alter schema logs. I'm not a huge fan of replacing functionality (there must be a reason why it was doing this -- yes? Could just be forgetfulness, idk..) so I added the functionality to choose.

Ask yourself these questions...

What if someone wanted to log the sync() but not the queries?

"Fixing" the logging for the behavior to act as a "global var" wouldn't suit this person's needs. They would either have to clog their pipes with either no logs or every log.

What if someone wanted to log only queries, but didn't care about the first initial schematic alterations?

This person knows what force: true means and what it does, but they want to log all of the queries (especially if they get a lot of visitors). If we were to make a "global logging" function, they too, would be screwed. :p

So we this in mind, we have two thought processes. So.. I'm not just going to throw a scope variable around the entire Sequelize core. I'm just going to make it a small option, it'll only be "thought of" once (or should).

But this doesn't solve a much bigger problem, I think both of us are on the right track actually. We should take your logger functionality and the concept of "multiple-needs-and-wants-to-log" and extend it as much as we can.

With your logger system I can have a winston adapter associated with it. The problem is, I can make multiple transports with winston, but Sequelize really doesn't have a protocol for exchanging information (and what types of information) to different outputs. It just knows it needs to throw a log somewhere :p

What if we were able to log sync, queries, read-only queries, write-only queries, why not even findAll-specific queries, etc?

We can extend the question even further to.. what if we can tag certain queries and funnel those queries to a specific location? Or speak to a service over HTTP, TCP, UDP?

Let's not get to crazy :p ... let's just start with the basics first, but if we can offer this extensibility while offering a minor performance hit (again, stressing on the word minor) why not?

[sdepold]

I will change the code, so that the current specs are correctly working. I will do some more work on that topic afterwards. Me current idea is to specify different logging types which can enable different logging mechanisms:

new Sequelize('db', 'user, 'pw', {
  logging: {
    sync: null /* I would go over to null instead of false, as it seems more consistent */,
    find:   console.log,
    destroy: function(sql) { mysuperawesomelogger(sql) },
  }
})

Where every part is defaulting to console.log

[mickhansen]

https://github.com/visionmedia/debug

Perhaps this would be a fit. (I have thought about implementing that in sequelize actually, to give people fine grained control)

[sdepold]

So imho, this PR is good to go. Thoughts?

[mickhansen]

I haven't had a time to look at it yet. @janmeier?

[janmeier]

Why is calledOnce false if we are expecting the to have been called?

[mickhansen]

He's testing that console.log isn't called

[janmeier]

But shouldn't console.log be the default?

[mickhansen]

Right :D

[janmeier]

I think the syntax should be sinon.spy(console, 'log')

http://sinonjs.org/docs/

And perhaps also an afterEach function that does console.log.restore()

[sdepold]

Because we instantiated sequelize with { logging: false } => no logging

[sdepold]

ah wait you are perfectly right!

[sdepold]

fixed

[janmeier]

I'm a bit confused about the tests, rest of the code looks good to merge :)

[sdepold]

As I fixed the specs and you reviewed the rest, I'm gonna merge that on my own.