Log module

[bcardiff]

Implements Log module as described in #5874 (comment) #8847 (comment) . With most of the documentation needed to use it.
Replaces the logger usage in the compiler (the playground used it)
Mark logger module as deprecated.
I added an internal macro method to expand to types similar to JSON::Any and YAML::Any since I needed two of them.

Fixes #5874
Supersedes #6901

[ysbaddaden]

My main concern is the YAML file, for which I have some questions:

1. Is the YAML configuration an optional nicety, or is it required? It looks like all crystal applications that require "log" will now include this YAML parser and depend on libyaml which may not be needed (e.g. small CLI tools).

2. Can the YAML file to load be configured programmatically? A framework will likely prefer to have a ./config/log.yml for example, instead of having an out of place ./crystal_log.yml —and not have to meddle with environment variables.

3. Can Log be configured programmatically instead? Seems like it, but Log::Config is only about YAML so that's weird.

[straight-shoota]

@ysbaddaden

Re 1. the idea was that require "log" doesn't include the config parser by default and you need require "log/config" explicitly. It seems that the implementation behaves like that. log/config.cr is not required in log.cr.

Re 2. I guess you could do ENV["CRYSTAL_LOG_CONFIG"] = "./config/log.yml" in user code, but having a direct API to specify the config location would be preferable. It should also an option to pass in the configuration directly without the setup code trying to read any files.

I agree with 3. There should be an usable Crystal API for configuring Log. Not every application needs flexible configuration from an external source.

[asterite]

Where is Log::Context used?

I see it can be set, read, etc., but I don't see it used. Also, when I do Log.info { ... } I can't see it in the output.

Is it there so that formatters can optionally use it? If so, maybe provide an example of such formatter?

[bcardiff]

@ysbaddaden The Log::Builder allows programmatic configuration or by redefining the Log.setup(config : Configuration) method you can setup the whole configuration you want. No yaml and no env vars is required. But it needs to be in that method if you want to be able to hook into the initialization of constants I am propossing to use. Using the Log::Builder allows use create loggers that are not reachable from the Log.for method.

@asterite I will add the output of the context to the stdio backend. Yes, there will be a Symbol#to_s I guess that is what you are thinking about it.

[bcardiff]

@straight-shoota / @ysbaddaden . regarding 2. There are some method that are defined in log/config.cr that are :nodoc:, by overriding the Log.setup you could reuse them to specify custom sources for the yaml configuration.

In particular overriding Log.yaml_config_path you choose another path. And by overriding Log.setup you can call setup_from_yaml with whatever you want. If these two scenarios work I can make them public and add some documentation to them.

[straight-shoota]

I don't think customizing the setup process should require reopening stdlib classes to redefine methods.
I'd prefer if Log.yaml_config_path was a property and allows to assign a custom path or disable YAML file loading.
Can we make Log.setup use a proc? And probably rename it, so that the public API method Log.setup receives a proc, like this:

require "log"
Log.setup do |builder|
  builder.bind "*", :info, SomeBackend.new
end

[bcardiff]

@straight-shoota

Can we make Log.setup use a proc?

The challenge is how the logs initialized in shards or std-lib will grab that configuration. If it is a method with proc the evaluation order is not error prone. We could have some macro to hide the redefinition of the method. But I don't think a plain proc will be enough.

require "myshard"
# shard
module MyShard
  Log = ::Log.for("myshard") # use the current configuration
end

# my app
Log.setup do |builder|
 # ... but the MyShard::Log could be already initialized at this point
end

[straight-shoota]

I see. Making Log.setup a macro that redefines the method might be a good idea 👍

[bcardiff]

@straight-shoota the last commit changes Log.setup to macro. Is a bit uglier than I expected.

• there is a need to tell if the configuration was done (truthy/falsey block value)
• since it is a macro, the block argument needs to used as {{config}}. (plain config work but only because the underlying declared method uses that as a method argument and the block would become superfluous)

[asterite]

As I understand it, right now the setup needs to happen before you call Log.for(...), right?

Why is that so? Can't Log.for("...") just give you some logger registered with that name, and setup configures them at any point in time?

[bcardiff]

How you ensure the logs are configured properly for the very first entry?

If we support reconfiguration of existing loggers we can mitigate a bit the issue, but still some logs might be emitted to invalid sources. So I think we need to setup loggers before any Log.for is returned.

[asterite]

How you ensure the logs are configured properly for the very first entry?

If we allow changing the log configuration at runtime, then everything is properly configured for the very first entry: with default values (I guess stdout).

I don't think it matters much if a few log lines are written to an incorrect place. Usually one would configure logging before the main code.

That's why I also think the Log configuration should be explicit in code, with something like:

Log.configure do |config|
  # ... 
end

If it's hidden behind a require "log/config" it's not clear.

(the above snippet can also be Log.configure_from_yaml_file("...")).

[asterite]

In general, explicit > implicit.

[paulcsmith]

I agree the explicit would be clearer and more customizable. For example you could remove the need to set an ENV var or have a particular yaml file. You could do Log.configure_from_yaml(ENV["MY_CUSTOM_NAME"]) or an explicit string like @asterite. Nice and clean, less implicit code to learn, easier to document

[RX14]

The datum macro seems very premature. Could it be introduced as a seperate PR, after this one and see what code it cleans up?

[RX14]

Looks good so far, this is just a preliminary lookover.

[bcardiff]

With the last push I removed Log::Config, all the yaml related support and the RegisterBackend annotation.

Now a Log::Builder is exposed in Log.builder that is the one used by the top Log.for. It allows reconfiguration of existing logs via Builder#bind and Builder#clear methods.

The Logs are tracked via weak refs in case to avoid leaking them.

The builder is thread-safe.

The top level docs are updated

---

• @RX14 the datum is extracted from JSON and YAML any. It can replace both actually. But is a private macro, to avoid making it public. It can evolve there I think.

• regarding file/line, it could be added to entry, the string should be already in the binary so there is not much runtime penalty to have them. But I am still hesitant to add it to every entry. Wouldn't that leak to much information of the machine used to build the source?

[RX14]

Thanks for this, I love it!

[straight-shoota]

🍰

[bcardiff]

Thanks everybody for the feedback and the discussion on this topic. I'm happy with the outcome.

[bew]

A great PR, it was a bliss to read 👌
Thanks a lot for this!!

Here are a few comments for a later cleanup pr 🙃

[bcardiff]

Since the final state of the PR changed from the initial proposal, I wanted to submit an updated version of it. Although the docs are available as well.

---

Generating logs

The are a couple of severity levels it can be used to emit logs: debug, verbose,info, warn, error, fatal.

Usually you will type Log.[level] { "a message" }

Log.info { "Hi there!" }

Note: Using the result of the block for the message will allow the runtime to ignore possible conversions, string interpolations to build the message if it is not going be emitted.

The Log is a new top-level constant in the std-lib (Logger will be deprecated and removed).

When generating logs you will use a Log instance. Each Log instance is bound to a source or path. Log.for(source : String) : Log will allow you get a new instance. The top-level Log acts as an instance of an empty string source Log.

When defining a new shard or module you will define a Log constant for that namespace.

module DB
  Log = ::Log.for("db")
end

Thanks to the relative resolution of constants, using Log.info { ... } inside DB types will resolve to the one previously defined and not the top-level one.

If you move code around during development, you will not need to deal with logger/@logger/@@logger substitutions.

If you need nested sources, you can use the parent namespace Log and avoid hard-coding the source name.

class DB::Pool
  Log = DB::Log.get("pool")
end

Or, if you want to hard-code it.

class DB::Pool
  Log = ::Log.get("db.pool")
end

Or, you can pass directly a type and the source will be inferred from it.

class DB::Pool
  Log = ::Log.get(self)
end

The result of Log.get(source) will return the same object instance for the same source. This will allow overriding the severity level of the log during specific moments programmatically.

Log.get("db").level = :verbose # or Log::Severity::Verbose
do_something_with_db
Log.get("db").level = :none # Log::Severity::None disables all levels

# DB::Log can be used instead of Log.get("db")

Note: Setting the level is specific to a source and not it's nested ones. The previous example doest not affect the db.pool source.

Note: Note that setting the level of a Log instance will affect all other Fibers that are concurrently using it.

When building a program it will be possible to ignore completely as part of the compilation the debug calls. So there is no penalty even to check if those logs should be emitted. The debug methods can be replaced by noop during compile-time. This will not be implemented initially.

You can also change programatically the logger level upon creation if you are hacking around.

class DB::Pool
  Log = ::Log.get(self, :debug)
end

Writing backends

The std-lib will come with a basic backends:

• Log::IOBackend to write to an IO
• Log::MemoryBackend to store logs in memory (it's suitable for testing)

But you can define your own backend by inheriting Log::Backend.

• #write(Log::Entry) will be called to write the given log entry.
• #close to close resources used by the backend

class MyCustomBackend < Log::Backend
  def initialize
  end

  def write(e : Log::Entry)
  end

  def close
  end
end

Whether the write operation in sync or async it will be up to the implementation. There might be some base modules to implement easily an async backends (similar to IO::Buffered).

Configuration

Configure logging explicitly in the code

Use Log.builder to indicate which sources should go to which backends.

You can indicate actual sources or patterns.

• the empty string matches only the top-level source
• * matches all the sources
• foo.bar.* matches foo.bar and every nested source
• foo.bar matches foo.bar, but not its nested sources

The following configuration will setup for all sources to emit
warnings (or higher) to STDOUT, allow any of the db.* and
nested source to emit debug (or higher), and to also emit for all
sources errors (or higher) to an elasticsearch backend.

backend = Log::IOBackend.new
Log.builder.bind "*", :warning, backend
Log.builder.bind "db.*", :debug, backend
Log.builder.bind "*", :error, ElasticSearchBackend.new("http://localhost:9200")

Configure logging from environment variables

Include the following line to allow configuration from environment variables.

Log.setup_from_env

The environment variables CRYSTAL_LOG_LEVEL and CRYSTAL_LOG_SOURCES are used to indicate
which severity level to emit (defaults to INFO; use NONE to skip all messages) and to restrict
which sources you are interested in.

The valid values for CRYSTAL_LOG_SOURCES are:

• the empty string matches only the top-level source (default)
• * matches all the sources
• foo.bar.* matches foo.bar and every nested source
• foo.bar matches foo.bar, but not its nested sources
• Any comma separated combination of the above

The logs are emitted to STDOUT using a Log::IOBackend.

If Log.setup_from_env is called on startup you can tweak the logging as:

$ CRYSTAL_LOG_LEVEL=DEBUG CRYSTAL_LOG_SOURCES=* ./bin/app

Implicit Context

The context information will live in the fiber. A new fiber will start with an empty context. Context are immutable but can be extended with convenient methods. The context are immutable so the backend can keep a reference to the context that was used when generating the Log::Entry.

The current context can be read from Log.context.

You can change the current context with clear and set methods.

Log.context.clear # => clears current context
Log.context.set request_id: 34, user_id: "[email protected]" # => extends the current context

When spawning Fibers you can inherit the context explicitly:

c = Log.context # current context
spawn do
  Log.context = c
  # ...
end

Log.with_context can be used with a block to restore to the previous context.

Log.context["request_id"] # => 23

Log.with_context do 

  Log.context.set request_id: 57689
  Log.context["request_id"] # => 57689

end # previous context will be restored at this point

Log.context["request_id"] # => 23

Other types

Disclaimer: this is more the structure description rather than the actual definition.

alias ContextValue = Bool | Int32 | Int64 | Float32 | Float64 | String | Time | Hash(String, ContextValue)
alias Context = Hash(String, ContextValue)

record Entry, source : String, severity : Severity, message : String, timestamp : Time, context : Context, exception : Exception?
enum Severity = Debug ; Verbose ; Info ; Warning ; Error ; Fatal ; None