Log Module Suggestions

I started working with the new Log module to get some logging setup in Athena. So far everything is going quite well. However, I have some ideas/suggestions that could be used to make it even better (IMO). Can update later if I/others have any other suggestions. From here if approved these can turn into issues or PRs.

Add context to log methods

To start, I really love the context concept. It makes it super easy to add context common to all logged messages. Sometimes tho, I only want to add context to a specific entry, such as that a route was found for the given request path. I found myself doing this quite often:

LOGGER.with_context do
  LOGGER.context.set uri: request.path, ...
  LOGGER.info ..
end

Thoughts on allowing entry specific context to be passed via the log methods? I.e. something like LOGGER.info uri: request.path { ... } Essentially if any context was given this would just pass the args to Log::Context.new and set that on the created entry. This would probably result in a few overloads similar to Log::Context.new.

Related to this, maybe also define an overload that accepts Log::Severity. Would be useful when you want to log the same thing but conditionally determine the severity.

Log::Severity::Verbose

Would it make more sense if this was below Debug?

Log::Context#to_json

Iā€™m using a custom IO formatter and JSON serializing the context is the easiest/most readable way to display the context within a line on STDOUT. This really would just be:

def to_json(builder : JSON::Builder) : Nil
  @raw.to_json builder
end

Log::Context#empty?

Related to the previous suggestion; it would be nice to know if there is any data that needs to be written in the first place. Main use case would be to prevent empty {} objects in the formatted entry. Something like:

def empty? : Bool
  case raw = @raw
  when Hash, Array
    raw.empty?
  else
    false
  end
end

Message Placeholders

Just a thought I had, donā€™t really care either way. The concept would be doing like:

Log.context.set user: "Jim"
Log.info { "{user} logged in" }

When logged the message would have {user} replaced with the value in the context. :man_shrugging:

Namespacing

Possibly move the default backends into a Log::Backends namespace? Downside would be longer type names. This could also be something for a feature of the docs command to organize things better without changing the actual FQN of the type.

Formatting

Currently only the IOBackend is formatable. One suggestion would be to extract this logic into a module. This module could be like:

module Log::Formatable
  property formatter : Log::Formatter

  def default_formatter : Log::Formatter
    # Some common format
    # Children could override this if they wish to change it
  end
end

Another related suggestion would be to support type based formatters. Could just be structs that implement #call to keep API the same as the proc formatters.

Log::Builder#append_backend

I can see internally there is a private method that adds another backend to the given Log instance. It would be nice if this was exposed, or at least a public version of it. The use case would be for creating a stack of backends that should be executed for each entry. This is already currently possible via Log::BroadcastBackend, but the docs on that say it shouldnā€™t be used directly, hence this idea.

Another idea would be allow Log::Builder#bind to also accepts an Array(Log::Backend).

NVM: This is already doable by binding to the same source multiple times with different backends.

Bubble

If a method is exposed to allow a stack of backends, it might be helpful to include a concept from the logger library we use at work called bubble. It essentially controls if an entry should be sent to the next backend. Essentially it is a boolean that defines whether a backend blocks the entry or not if they handled it. I.e. if you had two backends, A and B; if A had bubble set to false, and was able to process a given entry (i.e. its configured severity allowed it), then B would not execute. Otherwise if A was not able to handle an entry, it would be passed onto B.

I suppose this would only work well if the severity was on the backend side of things? It could be an optional thing that uses the severity defined on the backend or default to the severity provided when bound if the backend did not explicitly set one.

Processors

Most of the time, manually adding context is going to be enough, such as for context related to a given user action. E.x. user_id of currently logged in user. However, there are some use cases where you want some piece of data to be included in every entryā€™s context, but that doesnā€™t originate from singular source. E.x. say including git information. It wouldnā€™t really make sense to manually add this context as it would have to handle entries from multiple origins.

A processor would just be a type/proc similar to a handler, but ran before the handlers in order to add global context.

4 Likes

I guess it wouldnā€™t hurt.

No.

One argument is that eventually .debug calls could be removed from the release binary directly. If the severity is dynamic we wonā€™t be able to do that. Also, depending on the message you should be able to choose what is been emitted.

If you are building a facade or wrapper on top of this, you can do the dispatch there.

Itā€™s hard to remember, but debug is for debugging purposes and verbose is for a s**t ton of information that is usefull for a journal ā€¦ kind of.

No strong feelings. But maybe if you want that extension I would put it in ā€œlog/jsonā€ so json is not included on ā€œlogā€.

sure, in datum.

Use interpolations. The current design allows lazy expansion of them so there is no penalty.

:-1:

When time comes, sure. Another idea is to have a lazy backend that will perform the operations in another fiber for example.

That will tide up the ordering of backends. I havenā€™t seen that. But also, like the BroadcastBackend (although you are not supposed to create one explictly) you could have your own ChainedBackend to do some ad-hoc composite logic and registar that instance as a backend. Coming back to the lazy backend, it will be hard to know if the backed emit the log or not in that situation.

I donā€™t follow the example completely. A custom backed could be used to enhance the entry before submitting it. Or Log::Entry could be extended with some property with a default value I guess.


Thanks for playing around with the Log module.

1 Like

Thanks for all the suggestions! Iā€™ve got a couple thoughts as well:

Log::Context#empty?

I dig it!

Log::Severity::Verbose

Would it make more sense if this was below Debug ?

I would love to have this. There are definitely some spots where I basically want ā€œsuper verbose debugā€. Usually not useful but if you really need the info it is there.

This would be especially useful in shards because you provide verbose log info in all kinds of places that would normally overwhelm the user, but is helpful when you get into really tricky stuff.

Log::Context#to_json

Iā€™d love to have this for the same reason as @Blacksmoke16. I like the idea of log/json. Right now I have just extended Log::Context in Dexter to allow this

Allow struct or something as the formatter

Could be cool. My workaround has been to provide a Proc that wraps the struct: dexter/src/dexter/base_formatter.cr at af4feded4d31698e2c6d8e602516d54925540706 Ā· luckyframework/dexter Ā· GitHub

That way you can do MyFormatter.proc. I also did something similar for the old logger module so that I could do more complex formatting. Would be great to have this kind of thing as a Log::Formatter abstract struct that accepts an initializer with the Log::Entry and IO. Similar to what BaseFormatter does that I linked above. Then add that to the Log::Formatter alias so it or a Proc can be used

Here is an example of using the BaseFormatter

Yes the struct may be less performant but for stuff like Luckyā€™s PrettyLogFormatter we have to use one or the logic just gets too crazy

The other suggestions

I havenā€™t had a need for it so canā€™t really contribute to it. I haven nothing against it though

Some additional suggestions

Allow Nil as a type in Log::Context

Right now Iā€™m dealing with a lot of issues trying to handle Nil types. I think Nil should be a context type because it can be valuable to know something is nil

For example, if I have a context.set user_id: current_user.try(&.id) then I would expect it to work. Right now this is not possible and is messing up some logging in Avram. I think Iā€™ll need to monkey patch Log::Context to allow it but would prefer not to

Add formatter to IOBackend#new

Right now you have to do this:

backend = IOBackend.new
backend.formatter = MyFormatter
# Then bind it
Log.bind "*", :info, backend

Would be much nicer to do this:

Log.bind "*", :info, IOBackend.new(formatter: MyFormatter)

Proposal for different storage of log data

This will be a more complex proposal so will likely start a separate thread

Overall impressions

Aside from a few speed bumps like the Nil issue and and trying to get it working with a struct formatter it has been quite good. Dexter code is simplified tremendously now that Log has some kind of key/value storage

Happy to submit PRs

Some of my suggestions are simple. If theyā€™d be accepted Iā€™d happily open a PR

Iā€™ll make a PR for this.

Ah that would be pretty slick. :+1:

That would be doable yea. Only downside of that would be youā€™re making a backend do more than simply write an entry, plus that backend would have to be used in order to get that extra context.

Another way to think about it would be processors are similar to backends, but they just modify the entry/context, nothing more. Referencing my previous example, this could be like including the git commit hash in every entry, no matter how its logged or what backends it goes through.

I donā€™t really have an actual use case for this, its deff not as useful due to context being fiber specific, but still could have a use in the future.

I have a suggestion here: Proposal to have all data be key/value data in Log

That may affect your proposal to allow storing context data. I believe this ^ would solve the problem quite well and make it so you donā€™t need those additional args when you call info/debug/etc.

I think we left out nil because we only consider adding keys, and setting something to nil seemed like removing it. But probably we overlooked. Nil can be added I guess.

Sure.

I would say to start with shards for this. At least for now.

:heart:

:+1:

Awesome! Thanks @bcardiff. The hard part is doing that proposal in Dexter requires a lot of monkey patching, but I think I can just do that for now and gather some thoughts :) Will open up some PRs right now for that other stuff :tada:

Also, did we have a conclusion about moving Verbose as a lower level than debug?

To me it makes much more sense that verbose would be the most verbose setting, even more so than debug. Debug would be your normal debug messages and verbose is the ā€œhereā€™s everything, hold on tight :joy:ā€

For refernce: Thereā€™s now a discussion about VERBOSE severity: https://github.com/crystal-lang/crystal/pull/9107 (and about introducing TRACE and NOTICE).

1 Like

PR for adding overloads to log method for entry specific context