Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Refactor the entire logging system #1936

Open
jwoertink opened this issue Feb 19, 2025 · 1 comment
Open

Refactor the entire logging system #1936

jwoertink opened this issue Feb 19, 2025 · 1 comment
Labels
help wanted Additional expertise needed

Comments

@jwoertink
Copy link
Member

jwoertink commented Feb 19, 2025

At the moment Lucky uses Dexter to handle logging. This shard was originally written before Crystal did a massive refactor on their Log system. The current Log system that Crystal has built-in is pretty robust, but also infuriatingly complex ref.

The issue I'm currently running in to is that my app often makes random API calls to 3rd party systems. The HTTP::Client will only tell you what is being made if you set logging to debug; however, in development I set most of my logs to info because many of the logs are too noisy to actually see what's important. So at the moment, my log setup looks like this:

backend = Log::IOBackend.new
backend.formatter = Lucky::PrettyLogFormatter.proc
Log.dexter.configure(:debug, backend)
# Avoid so many "Executing query"
DB::Log.level = :info
Avram::QueryLog.dexter.configure(:none)
Redis::Connection::LOG.level = :info

This allows me to see more of what Lucky tells me, and less of what Redis, and SQL are throwing at me. With this setup, all HTTP::Client calls will just say "Performing request" and nothing else. This isn't helpful.

If I change that log setup for HTTP::Client, then it'll blow out ALL of my other Lucky logs.

Log.setup("http.client", :debug)

Blowing out all of the previous logs is actually mentioned in the API docs

Image

It's mentioned to use the block setup, and basically reconfigure all of the logs again.

Log.setup do |c|
  # note that with this call, the `backend` is required. You can't just leave it blank like the previous call
  c.bind "http.client", :debug, backend
  c.bind "*", :info, backend
end

The issue here is that this still won't work since the Lucky::PrettyLogFormatter.proc doesn't account for how the http.client log data is formatted. So you end up getting nothing.

Log.setup do |c|
  c.bind "http.client", :debug, Log::IOBackend.new
  c.bind "*", :info, backend
end

This "works" in that now I can see the HTTP::Client calls being made, but I can only see some of the Lucky logs. I see the request coming in, and the response, but I now don't see any output by Carbon, and I don't see what actions are rendering. My mosquito logs are also a little different now.

This leads to the new issue. We should be able to add and remove and change log statuses to different modules/shards/etc without worry of it affecting any other log setup. DB and Redis will never use Dexter since it just doesn't make sense for them so we need to account for other code we don't control and how it's configured.

Maybe Lucky can somehow monkey-patch Log in a way to "append" what we want. Maybe some helper methods to make things easier?

Half-baked idea:

backend = Log::IOBackend.new
backend.formatter = Lucky::PrettyLogFormatter.proc
Log.setup do |c|
  c.set_level(DB::Log, :info)
  c.set_level(Avram::QueryLog, :none)
  c.set_level(Redis::Connection::LOG, :info)
  c.set_level(Lucky::Log, :debug, backend)
  c.set_level(HTTP::Client, :debug)
end

Basically I just want something that I can pass the known class/module/struct/whatever and it just appends the log settings I want. I don't want to figure out that HTTP::Client is "http.client" in the logs, I want something else to just handle that for me. And whatever logs were previously setup, I don't want to blow out their settings. I want those to be left alone until I decide to override them.

Related: luckyframework/lucky_cli#863
Related: luckyframework/dexter#38

@jwoertink jwoertink added the help wanted Additional expertise needed label Feb 19, 2025
@robacarp
Copy link
Contributor

I know the crystal Log system is pretty opaque and the docs do not communicate well what needs to be done and by whom, but I've come to see it as a really powerful and flexible system.

In my apps, I have a config/logs.cr file which is the central source of truth for what log output happens and where it goes. I believe this to be the intention of the author of Log -- that the configuration happens at the end of the road at one place, not in several places or layers.

Here's an example:

Log.setup do |c|
  stdout = Log::IOBackend.new
  c.bind "*", :info, stdout
  c.bind "mosquito.*", :debug, stdout
  c.bind "asset_manager", :trace, stdout
  c.bind "db", :warn, stdout

  if App.env.development?
    c.bind "db.query_duration", :debug, stdout
  else
    c.bind "db.query_duration", :warn, stdout
  end
end

When I need to change the output, I always go here, and I can be wholistic or incredibly precise about what I'm logging. If I want to add an environment variable and use that to toggle verbosity, it happens here.


Then, as a library implementor, I don't worry about it at all. I choose a log-level scheme which is appropriate for the library and stick to it. It doesn't matter what other libraries think info and warn mean.

Well organized code which lives in modules is almost always easy to organize into the Log system with a single line addition to declare the namespace: Log = ::Log.for(self) -- that line becomes boilerplate for setting up a class. 90% of my Log usage is done this way.

In Mosquito, I also have some more dynamically created named Log streams. Log = ::Log.for(self) is a weird thing because it creates a constant called Log from a method on the global class Log. But that also means you can do @log = Log.for(object_id) and it'll nest under the constant:

module Foo
  class Bar  
    Log = ::Log.for(self) # creates a log steam called `foo.bar`

    def initialize
      @log = Log.for(object_id) # a log stream called `foo.bar.89237498`
    end

    def do_stuff
      @log.warn { "doing stuff" } # if log level for foo.bar.89237498 >= warn, emits "doing stuff"
  end
end

I'd advocate that Lucky and Avram come up with standards for what level of logging should be used at each tier (info/warn/debug) and just start emitting messages to Log. Dexter provided a possible vision for more flexible logging in crystal, but at this point stdlib went another direction and I think Dexter causes more confusion instead of simplifying anything.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
help wanted Additional expertise needed
Projects
None yet
Development

No branches or pull requests

2 participants