Proposal to have all data be key/value data in Log

Crystal Contrib
1

Based on some suggestions in Log Module Suggestions and some of my own thoughts on logging

TL;DR It would be helpful if all data in Log::Entry was key/value data

  • Key/value data is often more helpful for both humans and machines
  • It is a common pattern in most metrics system
  • Many loggers also have this format
  • Log consumers often provide a better search experience when data is key/value (typically formatted as JSON)

The proposal

I think we should have Log::Entry#context and Log::Entry#message_data.

I can already hear some criticisms ā€œsometimes I just want to log a String!ā€ or ā€œWhat about backwards compatability!ā€

I think these can be resolved quite elegantly and also allow for much better flexibility with how things are logged

Letā€™s dive into an example API

It looks the same!

Log.info { "Oh hai!" }

So for simple messages you can still pass a simple string like today.

Ok, but whatā€™s the new stuff?

Log.info { {query: sql_query, args: args} }

This letā€™s you provide data in a more human readable and machine readable format.

This is great because:

  • The simple case of logging a String is the same
  • Add the option to log key/value data

Under the hood

Under the hood a raw string message is assigned to Log::Entry#message_data as {message: "the string"}. So it is basically made into key/value data

Formatters

Now formatters can always rely on the data being in a key/value format. This is fantastic for JSON formatters or formatters like Luckyā€™s PrettyLogFormatter that does a lot of stuff to make logs human readable.

The default io formatter would basically change from entry.message to entry.message_data.to_s

The advantage?

Context is separate from the actual log data and allows better formatter

Right now the next version of Dexter basically makes this work using Log::Context to store the entry data dexter/src/dexter/log.cr at af4feded4d31698e2c6d8e602516d54925540706 Ā· luckyframework/dexter Ā· GitHub

The big problem with this approach is that context is mushed together with the log entry. Ideally Iā€™d prefer to print the message data first and then the context but that is not possible since I canā€™t tell which is which. There are also cases where I may want to ignore context data in a pretty log formatter, this is also not possible right now

EDIT: I canā€™t just reverse the context data because some of the data may be in a particular order. Like {failed_operation: "MyOperation", failure_message: big_array_of_messages_that_we_dont_want_first}

Backwards compatability

We can add a deprecated Log::Entry#message that basically calls message_data.to_s so it works with any custom formatters out there that rely on it (probably not a lot since Log is brand spanking new)

Can still print just the message data if you want

Your formatter could print just the message string if you really want to:

if entry.message_data.as_h.keys == "message"
  io << entry.message_data["message"].as_s
else
  io << entry.message_data.to_s
end

Next steps

I would be happy to open up a draft PR as that may make it easier to understand what I am saying, but I think there is nothing to lose, and plenty to gain.

  • You can still log just a string message
  • You can still have your formatter log just the string if you want
  • And also allows more flexibility for formatters to use the data (this is the big deal thing)

Seems like a win/win to me

1 Like
2

What would the benefit be over Log::Context? Especially when the the first idea from Log Module Suggestions is implemented. The way I think if of logging is a message with associated metadata that gives information related to given event/message, i.e. context. The message would be human readable while the context could be processed by machines in addition to the message.

Based on your example I would think Log.info(query: sql_query, args: args) { "Fetching users" } would be a better API. Since each backend/formatter has access to the Log::Entry they are free to access the context object to do whatever to it, while also having access to the other entry properties. Based on that Dexter link, what youā€™re doing seems kinda redundant versus just using the new Log module directly. Especially since there is now an actual container/structured way of storing context versus only having the message to work with.

1 Like
3

Hey @blacksmoke16! Great question. I didnā€™t explain that thoroughly. Here is the main thing:

^ That is one of the big reasons. And then the followup was showing how I canā€™t just reverse the context data.

Not all logs have a message

The other part of this is that: Log.info(query: sql_query, args: args) { "Fetching users" } doesnā€™t work in most of the places Iā€™m logging from within the Lucky shards. If Iā€™m logging the query or failed query the only message is the data. There isnā€™t really anything else to include. Same for logging http requests, exceptions, middleware, failed saves to the db, etc.

These are all things that donā€™t have a ā€œmessageā€ per se, but a set of helpful data.

So thatā€™s why I propose it always being key/value data. It enables a lot more possibilities as mentioned above, and you are still free to log just a message if you want! Best of both worlds.

I also think lots of ā€œmessageā€ data could be more valuable as key/value. For example: `Log.info { {user_id: 123, event: ā€œFinished taking the testā€} }

Now you can easily parse this as JSON, or search your logs for the ā€œeventā€ key for all events, etc.

Perf downside

The other downside of the approach you proposed is performance

Log.debug(data: a_non_trivial_method) { "Fetching users" }

a_non_trivial_method will run every time, regardless of whether the log level is set for it.

The only way to do it with the same performance characteristics is to do it inside the block. Which means either key/value data or a single primitive like a String or Int32.

You could do something weird like {{my_data: "foo"}, "message"} but that seems odd. Prob better to just do the NamedTuple or Hash IMO

Examples

I found a few examples of people using the logger, and how key/value data can help Code search results Ā· GitHub

Log.info { "Scheduled job with ID #{jid}" }
Log.info { {scheduled_job_id: jid} }

Log.info {"Login successful: #{username}"}
Log.info {{login_successful: username}}

Log.info { "#{service}: #{context.request.method}: #{proxy_path}" }
Log.info { {service: context.request.method, proxy_path: proxy_path} }

Log.info "#{version} serving application \"#{settings.name}\" at #{host_url}".to_s
Log.info { {serving_application: settings.name, amber_version: version, host: host_url }

There are also a bunch that are just ā€œmessagesā€

LOG.info("Initialising new project")
settings.log.info "Shutting down Amber"
# etc.

So they are definitely there, but these will still work with the proposed API so I donā€™t see them being a problem.

Summary

  • Many log entries donā€™t have a ā€œmessageā€ at all
  • Can still use just a String message if you want. Can do {user: "someone", message: "doing a thing} or just giving it a String like you can now
  • Performance is better because the block only runs for the appropriate level
  • Formatters donā€™t have to worry about some data being key/value and others not. Itā€™s all key/value
    • But they can check the message_data["message"] and print it without they key if they want!
    • This means you can still have all the existing behavior, but we also have new possibilities as mentioned above

What do we lose from going key/value?

This is the part Iā€™m most confused by. It seems that all of the examples given can be done with key/value data or a string, but many of the ones Iā€™ve given are hard/impossible cumbersome to do as it is now.

Is there something that this proposal makes more difficult? And if so, does it make it impossible?

For the use cases I listed I have to monkey patch Log to get the same performance and get it in the format Iā€™d like, whereas I think that would not be necessary if we do the key/value approach. Thoughts?

4

I think we just have two different points of view of how logging should work.

I think this is a flawed way of thinking. Why try so hard to just not give a simple string to identify a unique logging point? It would be much easier to search for logs if you had a static string to search against as opposed to arbitrary possibly dynamic data.

Plus you could just provide context and an empty block, which would evaluate to an empty string message.

Sorry, I just fail to see how this is better than Log.info(user_id: 123) { "Finished taking the test" }, especially when this already essentially does what you want.

You got me there. However I donā€™t think its that big of a deal. Most of the time the context would be data you already have available. Plus if you really needed you (or the stdlib) could define an overload like
def self.info(ctx : Proc(Log::Context, ...) which would only be called when it is going to set the context, i.e. if the entry is going to be logged.

This is biased search. Last commit on the majority of those is over 2 years ago. I.e. when the new Log module didnā€™t exist and there was no concept of Log::Context, thus they had no choice but to include it in the message.

Unfortunately, there is probably not a lot, if any, data about this just due to how recently the new module was released.

I see where youā€™re coming from, but I just donā€™t think itā€™s worth it, especially now that we have Log::Context as a more proper way to store structured data with an entry.

5

I think this is a flawed way of thinking. Why try so hard to just not give a simple string to identify a unique logging point? It would be much easier to search for logs if you had a static string to search against as opposed to arbitrary possibly dynamic data.

Hereā€™s the thing, I think you are right! We have a different way of thinking. I donā€™t think my thinking thinking is ā€œflawedā€ and yours isnā€™t either. We have different goals and opinions, which is great!

But I canā€™t do what I would prefer and meet my goals with the current implementation. I have to monkey patch all kinds of things on Log. But with my proposal you can still log a message string

So why not do it? Iā€™m not sure I understand. There is no downside if you want a String message as far as I can see?

It would be much easier to search for logs if you had a static string to search against as opposed to arbitrary possibly dynamic data.

Iā€™m not sure I understand this. It would still searchable based on the key or the message data. You can still pass whatever messages you want so it is just as searchable. Weā€™ve been doing this since Lucky started so I donā€™t totally get it. Maybe an example would help?

For example I can search ā€œqueryā€ or ā€œfallback_actionā€ or any number of keys. It seems no more/less searchable than a string to me

6

Also I am curious how you would use a message in these examples. Not trying to convice or whatever because I think we have different perspectives, but Iā€™m trying to learn so I can understand your position better:

These all seem like to me there is no ā€œmessageā€ that would help and these are still searchable, but maybe I am not understanding. Would love to hear what you think

But either way I can keep monkey patching if I need to. I did that before so I guess not too big of a deal :man_shrugging:

7

Why not just use the features the Log module provides? Youā€™re fighting against the implementation so that you donā€™t need to provide a message. You still get structured data, and can now control the order of that context in relation to the message.

Iā€™d expose the type of the query that failed. Something like Log.info(query: @query, args: logging_args) { "Failed to query #{T}" }

Log.warn(fallback_handler: fallback_action.name.to_s) { "Handling #{context.request.method} #{context.request.path} via fallback" }

Log.warn(handled_by: handler.payload.to_s) { "Matched route #{context.request.method} #{context.request.path}" }

8

I feel that is superfluous information but I get what you are saying and respect that you want to go that route. As discussed in gitter Iā€™ll just drop this since what Iā€™m doing is flawed and doesnā€™t seem to be wanted

Iā€™ll monkey patch and just go that route :+1:

9

I believe your changes with a couple tweaks would fulfill both our needs :slight_smile: Left comment here: https://github.com/crystal-lang/crystal/pull/9110#issuecomment-615258676 for anyone following along

10

Well for one, it adds additional complexity. That complexity is not only added to log systems that want to use that, but to everyone using Log.

What I donā€™t fully grasp is the difference between message_data and context. As far as I understand it, context is the feature yourā€™e looking for to map key-value data to log entries. I fail to see what a difference it would make to have an additional message_data property which would essentially do the same thing. context is already fully customizable. You can use it as you seem fit in your application. So you could just add a message_data property to the context if that helps your use case. Using a custom formatter you can easily print message_data values before all the others.

A related but different question is whether a message string should be mandatory for every entry. Iā€™m not completely settled on this, there are certainly different philosophies. Either way, you could always get what you want by either setting message to empty string or adding a message property to the context. Itā€™s just about what Log suggests as default behaviour.

11

Yes I have since revised my proposal here: Some `Log` improvements by Blacksmoke16 Ā· Pull Request #9110 Ā· crystal-lang/crystal Ā· GitHub

The new proposal just uses context and would pretty much solve the issue:

# still works!
Log.info { "my message" } 
# This is new and is basically your proposal but with context in the block for perf reasons
Log.info("my message") { {my_data: "foo"} } 
# This is also new. Same as above, but sets message to ""
Log.info { {my_data: "foo" } }

But the data is stored in the Context under a local key.

What I donā€™t fully grasp is the difference between message_data and context . As far as I understand it, context is the feature yourā€™e looking for to map key-value data to log entries. I fail to see what a difference it would make to have an additional message_data property which would essentially do the same thing

The end goal can be solved by storing the data in a local or message_data key. You are right and I just didnā€™t think of that :) But the goal is to keep them separate somehow so I can have log formatters log just the local context or both. Another goal is for the Luckyā€™s pretty log formatter to only log the global context when it changes. So weā€™d need stuff stored in local or some other key.

As you said, this is possible now but is a pain. Having those 2 new methods that allow setting local context per entry would be amazing. If not I can monkey patch Log to allow it

A related but different question is whether a message string should be mandatory for every entry. Iā€™m not completely settled on this, there are certainly different philosophies. Either way, you could always get what you want by either setting message to empty string or adding a message property to the context . Itā€™s just about what Log suggests as default behaviour.

Yeah I am not sure either. In the current implementation I think it makes sense. Iā€™ve since realized I can just ignore an empty message in my formatters and that seems to be working fine.

Summary:

This is basically what Iā€™m asking for. Keeps backwards compatability. Log::Context and Log::Entry remains the same. Existing formatters still work as-is. All this does is allow setting key/value data in the block (and adds an option to do a string message and key/value data. Personally I wonā€™t use that, but I can see why it might be handy)

def info(message = nil, *, exception : Exception? = nil)
  # ...The logic for early return remains unchanged

  block_result = yield

  if block_result.is_a?(NamedTuple) || block_result.is_a?(Hash)
    Log.with_context do
      Log.context.set(local: block_result) # Set local context data
      # Set empty message
      write_entry_to_io(backend, severity, message: "", exception: exception)
    end
  else
    # Don't set context, just set the message from the passed in
    # Works with the `message` arg or with a string, int, etc. returned from a block
    write_entry_to_io(backend, severity, message: (message || block_result).to_s, exception: exception)
  end
end

private def write_entry_to_io(backend : Backend, severity : Severity, message : String, exception : Exception?) : Nil
  entry = Entry.new @source, severity, message, exception
  backend.write entry
end
12

Iā€™m not fond of removing message and leaving every entry as K/V structure only. There is some simplicity in the string message.

I donā€™t think we need to worry about context with heavy computations in the log context. Information should already be there: required for the program to work. Is there an example for this requirement?.

When iterating over the design we thought on allowing the Log::Entry to be modified in the .info { ... } block and inject there additional context. But none of the options were as simple as we liked it. So we cut them.

If we accept that context should be lightweight, the following API (+ some variantes for dynamic context) could work.

# Log#info(**context, & : -> String)
Log.info(user_id: user_id) { "Logged in" }

Note that that syntax will clash a bit with how exceptions are attached to an entry.

Since logging messages will probably involve interpolation we wanted to resolve them lazy in case the entry is not needed. For the context that should not be the case.

13

@bcardiff

Iā€™m not fond of removing message and leaving every entry as K/V structure only. There is some simplicity in the string message.

I agree and have walked back on that. In my proposal above it still keeps it :+1:

I donā€™t think we need to worry about context with heavy computations in the log context. Information should already be there: required for the program to work. Is there an example for this requirement?.

Yes I have a couple.

So many may have the context ready, but for using the context to log data it would not be ideal to add this extra computation if the message will not even be used.

So Iā€™d prefer to have it in a block for those reasons. I assume I am not the only one who will want to do things like this.

I would probably be ok with

Log.info(user_id: user_id) { "Logged in" }

But would love it if there was an option to not pass a message at all. If it does tha tis ok and dexter can have custom overloads, but not all messages need a message IMO. Setting it to an "" would be great, or if we use the other API I proposed you would just pass a block and message would be a string

I think is still a very simple API, works performantly and still works great with exceptions!

# This is new and is basically your proposal but with context in the block for perf reasons
Log.info("my message") { {my_data: "foo"} } 
# This is also new. Same as above, but sets message to ""
Log.info { {my_data: "foo" } }
# With an exception
Log.info(ex) { {my_data: "foo" } }
Log.info(ex, "my message") { {my_data: "foo" } }

Context ā€˜localā€™

The other part was adding this data to a local key in Log::Context so formatters can format local context from global context different if they choose. If not they can just leave it there, but itā€™d be nice to allow formatters to do that

This is a ā€œmust haveā€ for Lucky to keep logs nice. For example, in JSON logs weā€™d like to print local context before global context. And with a the pretty printer log weā€™d like to only print global context when it changes. If all the data is in the top-level there is no way to differentiate ā€œglobalā€ context from ā€œlocal/entry specificā€ context.

So we (Lucky team) could monkey patch or add our own overrides in Dexter to accomplish this, but it seems these things would help everyone and could be done with very minimal changes to Log. I provided a near complete implementation above in ~30 lines of code. Not perfect but just shows this is not a big change and it is backwards compatible in every way

Thoughts?

14

Context are not hierarchical, they are merged. But there is nothing from doing something like

Log.with_context do
  parent = Log.context
  Log.context.clear
  Log.context.set local: 2, parent: parent
end # => parent is restored as Log.context

Regarding the lazy context, I noticed they are available already :-).

Log.with_context do
  Log.info { Log.context.set(b: 2); "Info with lazy context" }
end

Since the with_context has almost no cost maybe we can invoke it on every action around the block.

The Log::Entry#context gets itā€™s value from Log.context after the block .

1 Like
15

Yeah Iā€™ve got something similar where I store the context under ā€˜localā€™ and that seems to work. I added a method to Log as well that makes it a bit easier to set.

Itā€™s all good if not added, just thought it might be a nice thing to have

And that is cool about the lazy context. I hadnā€™t though of that! So cool :D

16

Here is what I ended up doing with Dexter. I added a Log.dexter that returns a Log::Dexter struct so it has 0 conflict with Log. You can do Log.dexter.info/warn/etc { {my_data: "foo" } } and it will be addws to Log.context under the local key. Then the JSONLogFormatter handles the local key specially and makes sure it is in first the spot we want it, but is totally compatible with all Log, not just Dexter. So anyone can use dexter even if they just want to the JSON formatter. Iā€™m pretty happy with this

If curious, here is the implementation. Itā€™s quite simple in the end!

So we can close this if it is not desirable to anyone else. If curious though, give Dexter a try once we officially release 0.2.0 and update the README :

17

Note that the docs says

Log.dexter.{{ method.id }}(exception) ->{ { query: "SELECT *" } }

instead of

Log.dexter.{{ method.id }}(exception: ex) { { query: "SELECT *" } }

Since you also wanted to have some custom structure of the context, I think that the Log.dexter extensions is write.

Youā€™ll probably want to define def self.dexter in ::Log also.

18

Oh thatā€™s right I changed it to use a block and forgot to move it back. And good call on self.dexter! I forgot about that use case

Thanks

19

@caspiano did something similar for our use cases.

Basically allows you to do something like
Log.info { {key: value, message: "the message"} }

Then uses the log context to set the additional tags, extracting the message.