Logging

[jodosha]

This is a proposal to add:

• Optional logging for database operations while the application is running
• Automatic logging to $stdout when running migrations

---

Logging for database operations

This is optional when using hanami-model in standalone, but it will be enabled by default for Hanami projects (hanami gem).

Usage

Hanami::Model.configure do
  # ...
  logger "log/development.log", level: :debug
end

Where the first argument is a IO Ruby object: a path to a file, or $stdout.

Again, this will be setup automatically in Hanami projects

Example

app=hanami.model severity=INFO time=2017-01-03 17:17:17 UTC message=(0.000260s) SELECT `id`, `name`, `created_at`, `updated_at` FROM `authors` WHERE (`id` IN (1)) ORDER BY `authors`.`id`

Automatic Logging for Migrations

This is always enabled without any configuration.

Example

[migration] [INFO] Begin applying migration 20160831090612_add_rating_to_reviews.rb, direction: up
[migration] [INFO] (0.000209s) BEGIN
[migration] [INFO] (0.004497s) ALTER TABLE "reviews" ADD COLUMN "rating" integer DEFAULT 0
[migration] [INFO] (0.000191s) INSERT INTO "schema_migrations" ("filename") VALUES ('20160831090612_add_rating_to_reviews.rb') RETURNING "filename"
[migration] [INFO] (0.001470s) COMMIT
[migration] [INFO] Finished applying migration 20160831090612_add_rating_to_reviews.rb, direction: up, took 0.007864 seconds

This is too much verbose IMO, but we don't have control on it, as we use Sequel logger for that.

---

/cc @hanami/issues @hanami/ecosystem @davidpelaez for review. 👍

---

Closes #277

[pascalbetz]

Why passing the stream and not a Logger?

[mereghost]

From what I understand he will build the logger later on.

[pascalbetz]

Wouldn't it be easier to pass the logger? I don't see that it's the Migrators responsibility to build it. Harder to configure logger/pattern like this, no?

[jodosha]

@pascalbetz @mereghost TBH, I injected that dependency only for testing purposes, but I don't like it. Also, look at how many times is passed down from method call, to method call, deep in the stack.

I can refactor it, by adding a Configuration#migrations_logger as private API, so we can remove it from all these method signatures and have an easy access to stub it during test.

[mereghost]

👍

[mereghost]

What do you think of introducing a NullObject/Mimic logger? With ti we would not check for nils and it would simply do nothing. Yeah, one more method call, but cleaner code.

[pascalbetz]

👍

[jodosha]

@mereghost @pascalbetz By avoiding the call to use_logger, we avoid the overhead of thousands of useless method calls against a null object.

Because once gateway receives a logger, it uses it. It wouldn't log, because it's a null object, but still it invokes methods on it. Which is a useless overhead.

WDYT?

[pascalbetz]

Wouldn't we have a logger set most of the times anyway?

[TiteiKo]

@pascalbetz In development, yes, but not necessarily in production

[AlfonsoUceda]

At least in production we don't log SQL queries, only the needed.

[pascalbetz]

I see.

Here is a benchmark, so we can make informed decisions:-)

Comparison:
no logger, nil check: 8778993.1 i/s
null logger, call: 6309574.3 i/s - 1.39x slower

require 'benchmark/ips'


class NullLogger
  def info(message)
  end
end

class Something
  def initialize(logger)
    @logger = logger
  end

  def work_with_null_check
    @logger.info('working hard') if @logger
  end

  def work_without_null_check
    @logger.info('working hard')
  end
end

null_logger = Something.new(NullLogger.new)
no_logger = Something.new(nil)

Benchmark.ips do |x|
  x.compare!
  
  x.report('null logger, call') do
    null_logger.work_without_null_check
  end

  x.report('no logger, nil check') do
    no_logger.work_with_null_check
  end
  
end

[mereghost]

From what I understand he will build the logger later on.

[AlfonsoUceda]

double :warn and :info

[AlfonsoUceda]

At least in production we don't log SQL queries, only the needed.

[jodosha]

@mereghost @pascalbetz @TiteiKo @AlfonsoUceda I've refactored, according to your requests. Please review. 😄