Duped log messages when working with Lucky+Mosquito

[robacarp]

This is on release lucky and dexter, not master. It's possible this is fixed somewhere already.

---

I can't seem to actually prove that I know what's going on so I'm hesitant to open an issue here or on Dexter.

In plain English: when I have a lucky app with a mosquito worker entry-point, the log messages emitted from mosquito jobs are duped. The first message is emitted with what appears to be the standard crystal formatter, and the second is reformatted with the LuckyFormatter.

In this screenshot, "Performing Scheduler Job" is emitted from within a Job's #perform method. Everything else is emitted by Mosquito's runner class (the main loop of a mosquito worker).

---

Mosquito Jobs register their logger a bit differently than the rest of mosquito:

• The logger is registered on the class instance rather than the class itself. This is probably unnecessary, but it's what's currently happening.
• A new log object is created at runtime rather than statically at compile time, and that object is re-created with every log message. Again, probably unnecessary.

There's obviously some refactoring work which needs to be done in Mosquito around this -- it's not currently possible to emit anything but an info level message, for example. But I also don't think mosquito is doing anything which isn't expected by the std lib Log class.

---

I injected this into my Log class to try to sort out what's happening:

class Log
  class Builder
    private def append_backend(log : Log, level : Severity, backend : Backend)
      if log.source == ""
        raise "appending backend for #{log.source}: #{backend.class}"
      end
    rescue e : Exception
      puts e.message
      puts "\t#{e.backtrace[1..-1].join("\n\t")}"
    ensure
      previous_def
    end
  end
end

Which results in this output. I've trimmed out the crystal core libs for brevity:

appending backend for : Log::IOBackend
	lib/dexter/src/dexter/log.cr:31:5 in 'dexter'
	config/log.cr:22:3 in '__crystal_main'
appending backend for : Log::IOBackend
	lib/dexter/src/dexter/log.cr:84:7 in 'configure'
	config/log.cr:22:3 in '__crystal_main'

Quick links to those lines in dexter: dexter/log.cr:31 dexter/log.cr:84