Crystal: Macro def overriding base class method but only when used in an instance variable

[paulcsmith]

Crystal 0.27.2

This is best explained with examples

This works as expected

require "logger"

module Dexter
  class Logger < ::Logger
    def formatter=(value)
      {% raise "raising from formatter" %}
    end
  end
end

logger = Logger.new(nil)

# Regular logger is unaffected. Can set a formatter :D
logger.formatter = ::Logger::Formatter.new do |severity, datetime, progname, message, io|
  "not used"
end

This does not

class SomethingUsingLogger
  def initialize
    # For some doing this as an instance var causes an issue
    @logger = ::Logger.new(nil)
    @logger.formatter = ::Logger::Formatter.new do |severity, datetime, progname, message, io|
    "not used"
    end
  end
end

# This raises the error from the Dexter::Logger even though we instantiated a ::Logger!
SomethingUsingLogger.new

This is not just an issue with the Logger class. Any child class that overrides the parent class method with a macro def and is then instantiated inside another class incorrectly calls the macro def from the child.

More details here: https://github.com/luckyframework/dexter/issues/2

[straight-shoota]

I'm not sure this is a bug. It looks like you're breaking inheritance when you try to forbid calling a method that is defined in a superclass. You shouldn't do that. When Logger implements #formatter, all child classes need to do so, too. It can raise at runtime, but not a macro raise because that will explode any time the method is typed.

This seems to be the case when an Ivar is of the parent type. Then the compiler assumes that it's value can actually be any of the child types. When assigned to a local variable, the compiler can be certain that the value can never be Dexter::Logger and skips typing the method in the child class. That's at least my understanding of this which might not be 100% correct, I didn't check the compiler code.

[paulcsmith]

This actually makes a lot of sense now! And I agree that is the correct behavior. Thank you for the clear explanation! I will change my library to print a warning instead

[straight-shoota]

Why change the method name anyway?
The readme claims, dexter is "100% compatible with built-in Crystal logger". That would include implementing all the methods from ::Logger.

[paulcsmith]

Yeah I guess it isn’t 100% compatible but setting the formatter doesn’t make sense with Dexter since it uses a different one

The reason it can’t use the regular formatter is that Dexter passes NamedTuples to the formatter. The built in logger just passes strings. So the formatters are just not compatible.

I’m thinking of opening a PR to the Crystal logger to use NamedTuples instead of strings in the formatter but I don’t have that much time to do that and work in all the Lucky shards

[straight-shoota]

Btw. are you aware of the initiative to redesign the stdlib's logger? #5874
I'm pretty sure the problems dexter tries to solve are relevant for the stdlib implementation as well.

[paulcsmith]

And the reason for using data instead of a string is that you can get machine readable logs (like printing to JSON) and you can also format it in all kinds of ways other than JSON (key value, l2met).

You can still log strings but it converts it to a {message: String} format.

Also IMO shards should not create a logger, but should accept a logger and keep whatever formatter is used there. The reason this came up is that another shard made its own Logger instead of accepting an instance of one. That’s bad because it ignore whatever logger the user wants (maybe they want a different log level, or to print to a file). A bit of a tangent but may be useful for future readers that stumble in this.

[paulcsmith]

Updated Dexter to mention this small caveat: https://github.com/luckyframework/dexter/pull/5

@straight-shoota I was not aware! I'd love to chime in. I think the ideas in Dexter would definitely be valuable in the stdlib