Added basic logging

[crisward]

I've tried this on my local dev env against an app and it works as expected. The logging isn't perfect but doesn't require any knowledge of specific db implementations.

A better logging system would give us queries including the args, and perhaps how long each query took. But this is pretty useful as is, so hopefully it'll get merged.

Thanks.

[RX14]

I think the interface should be DB.logger = ->logger(String) and use DB.logger = nil to disable it at least. I also think there's little point merging this if we're going to want to change the API later to implement showing query args and timing.

[crisward]

I added the logging = true / false because it's nice to be able to set up a logging method somewhere and enable disable when needed.

Also it may be simpler to implement a default logger, but allow it to be overridden with DB.logger = ... and nil can be used to revert back to the default.

I know what you're saying about not merging. But if the API stays the same the functionality can be upgraded later. To get query args and timing is a per driver implementation, which will obviously take longer to create and test across the 3 current drivers (Postgres, Mysql, Sqlite). The logger could still return a string.

[bcardiff]

Thanks for taking the stab here. Some comments:

I think the logger should not be global, but per Database. That could allow to turning it on/off for stdout via connection uri.

Is there a reason why not to use the ::Logger from stdlib?

Maybe is more useful to log when the queries are actually executed rather than just created. Even if this only works for pooled connection.

[crisward]

The proposed implementation I'm already using and switching the logging on and off at runtime, I've actually already found a bug with it (crisward/kemal-session-mysql#3). We now have a tickbox in our applications settings panel to enable database debugging.
I'm not sure the adding it to the url would make sense using it like this, though I do agree it should be per database.

I wanted the option of a callback so I could potentially pipe the output to something else other than std out. Ie Sentry, redis etc, and have control over the formatting. Though I do agree that is should also use Logger at debug level, perhaps as a default when no callback is setup.

I've had a look into getting the full query for prepared statements (with merged in args), it doesn't look like this is possible for mysql, though it may be possible to emulate this (with some evil looking regex). Getting query time involves setting a flag, then searching the information_schema table for some data. I'm very sure both of these things are going to be a per database issue. Both of these solution feel like hacks.

I'll update the pull request incorporating your suggestions. Any further feedback is welcome.

[bcardiff]

I would expect that the logging of a prepared statements would be something like

QUERY "SELECT * FROM Contacts WHERE age >= $1 AND zip = $2" WITH PARAMS: 33, "CSD4534"

So I see no need for regex.
At least on pool statements the query is saved in an ivar.
I would say that query execution should be INFO. And leave DEBUG for lower level things in database like resource management on protocol implementation.

The stdlib Logger uses io and the formatter can specify how to flush messages there, so maybe is enough to plugin that to Sentry.

[RX14]

How about "Running query #{query.inspect} with params: #{args.join(", ")}". I think human readable is better than shouting in all caps here.

[crisward]

I agree the logging could be a little better, but I quite like it stating with QUERY : as it stands out amongst other log entries. Within kemal, the default log follows this format with the http verb being in block caps.

2017-07-25 21:25:07 +0100 200 GET /duocms/api/groups 16.34ms
2017-07-25 21:25:07 +0100 QUERY "SELECT `id`,`name`,`order` FROM groups where deleted_at is null and id = ?" with params: 1

[RX14]

Why not just use @logger = ::Logger.new(STDOUT) instead? It's simpler and I don't see the need for supporting Logger.logger = nil.

[crisward]

That makes sense. I've updated that and will push shortly.

[asterite]

I think the enabled flag is not needed. The DB (or whatever object has the logging) should have a DB::Logger | Nil instance variable and a logger=(logger : ::Logger) method. When you set the logger, you set @logger = DB::Logger.new(logger). Basically:

module DB
  class Database
    def logger=(logger : ::Logger)
      @logger = DB::Logger.new(logger)
    end

    def logger=(logger : Nil)
      @logger = nil
    end
  end

  class Logger
    def initialize(@logger : ::Logger)
    end
  end
end

When @logger is nil, there's no logging. And then you can do @logger.try &.log() in calls, which will also be more efficient as it will avoid an extra call in every query (it will be just a nil check)

[eliasjpr]

Can this be merged any time soon? it has been a while

[rwojsznis]

Thanks for this @crisward ❤️ Ideally this should also probably log query runtimes for easier debugging, but it's definitely a start

And because this PR is super old as @eliasjpr mentioned - can we maybe merge it in current form anyway? I mean those changes proposed by @asterite - are those really needed at this stage? Is nil check really is better/faster that current instance boolean variable check?

Crystal ecosystem is kinda lacking "serious" tooling at this point so I think we should appreciate every contribution effort. Even if it's not the perfect proposal/solution, but does the job - it can always be improved later, right? Done is better than perfect etc.

Just my 3cents, cheers :D 😽

[rwojsznis]

Ping @bcardiff maybe?

Also cat gif for attention 😉

[bcardiff]

This will come after crystal-lang/crystal#5874 . I really want to see it done :-)

Nice cat gif. It's a good thing I am not allergic to them in gif format 🤔

[eliasjpr]

It would be great to allow use of a custom formatter. What do you guys think?

[eliasjpr]

Stale review!

[duraki]

Any update @RX14; @bcardiff? Is there alternative to hide logs?

if !ARGV.empty? && ARGV[0] == "--debug"
  Log = ::Logger.new(STDOUT)
else
  # => w/ this fix ...
  Log.logging = false
end

[Blacksmoke16]

Could also look into an implementation of https://github.com/Blacksmoke16/crylog.

The initialization of the loggers could be setup within a protected class method that gets executed within the main module.

def self.configure_logger
  # Do the setup here
end

This would allow projects/orms to override it if they wish to add extra functionality, custom processors, etc.

[Blacksmoke16]

At this point an implementation based on the new Log module would be best.