Open Drowze opened 4 months ago
Are you using structured logs (json format) into DataDog, or just the plain text logs?
Highly recommend json logs, which break out all the data elements for you, the controller name is just the name
entry in the JSON log. In human readable text logs the Controller name is present in the text before the message.
This is an example of how we switched our Kubernetes docker containers to log using json / structured logs. In application.rb
:
# Setup structured logging
config.semantic_logger.application = "my_app"
config.semantic_logger.environment = ENV["STACK_NAME"] || Rails.env
# Switch to JSON Logging output to stdout when running on Kubernetes
if ENV["LOG_TO_CONSOLE"] || ENV["KUBERNETES_SERVICE_HOST"]
config.rails_semantic_logger.add_file_appender = false
config.semantic_logger.add_appender(io: $stdout, level: ENV["LOG_LEVEL"] || config.log_level, formatter: :json)
end
Hey @reidmorrison, thanks for the feedback :)
We actually do use JSON logs! (actually it's a custom formatter - but it indeed outputs JSON-formatted logs that Datadog can consume).
For more context, here's an example of how JSON-structured logs are displayed in Datadog after you click them.
Notice we have all the nice details here (controller, action, params, some custom attributes set by our formatter...). I'm also able to search for those attributes just fine (so for an example, to search only for logs from the UsersController
I'd search for @payload.controller:UsersController
) but the message is still simply Completed #index
- and that is what ends up displayed in the logs listing.
The reason I'm looking forward to a change on the message
attribute is solely how the logs are listed (before you actually click on them to see more details). Taking for example the screenshots I attached, before clicking (or filtering on the search) we can't know for sure what controller those logs listed are referring to - we only know the name of the action they refer to.
According to the Datadog docs:
By default, Datadog ingests the value of the
message
attribute as the body of the event entry.
(Ideally I believe there would be some customization in the way that message
is built for the rails logs (perhaps using some templating, e.g. Completed %controller%#%action%
could be replaced by Completed UsersController#show
- but let this just be food for thought right now 😄 )
Btw, just for completion sake, here's how we're configuring SemanticLogger in production:
config.log_level = ENV.fetch("LOG_LEVEL", "info").downcase.strip.to_sym
config.colorize_logging = false
if ENV["RAILS_LOG_TO_STDOUT"].present?
$stdout.sync = true
config.rails_semantic_logger.add_file_appender = false
# REQUEST_EXTRACTORS is simply a lambda to extract e.g.: `method`, `url`, `useragent`, `ip`, etc...
# from the request, so that they can be attached in the logs through `log.named_tags`
config.log_tags = DdLogFormatter::REQUEST_EXTRACTORS
config.semantic_logger.add_appender(io: $stdout, formatter: DdLogFormatter.new)
end
With Splunk and Observe, they both allow you to choose what columns are displayed. Strange that Data Dog is preventing you from being able to display the log event name
column.
Without these basic columns, not sure how useful Data Dog can be with structured logs (JSON format).
I would contact your Data Dog rep and ask if you can add the name
column to your view. If it is not possible, you could change DdLogFormatter
to change the message to include the name log.message = "#{log.name}: #{log.message}"
.
Not saying we can't chose the columns - we definitely can! Adding/removing columns is easy (and we can also save the view for later usage)
The content
column (which is the .message
JSON attribute) is a pretty particular one though, since it is shown by default on the listing to anyone who doesn't customize their view and is also the only json field searched by default with full text search (unless we specify another json field in the query) - to better illustrate, here's some examples of searching logs in Datadog:
# searches logs where `.message` JSON attribute CONTAINS 'hello'
hello
# searches logs where `.logger.name` is EQUAL TO MyController and `.message` CONTAINS 'hello'
@logger.name:MyController hello
# searches logs where 'hello' is CONTAINED in ANY json attribute (note: this is a very new Datadog feature)
*:hello
...so that's why I'd personally like to get more flexibility over what is carrier over on the .message
attribute of the logs. Although I'm repeatedly mentioning Datadog, I'm sure that customizing the log message would be a neat feature regardless of how the logs are consumed.
I think just customizing the message like you said (log.message = "#{log.name}: #{log.message}"
) works alright for us today and we'll probably go for that route for now - but maybe in future having more control over message
is something that rails_semantic_logger
can consider 😃
Please merge this PR @reidmorrison, I've just set up rails_semantic_logger
and I noticed the same thing, DataDog displays by default Completed #index
so it doesn't mention the controller in the message 😞.
If you are not happy with this change, I think there should be at least a way of customizing the message to have the way we want (via a proc for example).
Custom formatters can be supplied both via a proc and custom formatters that inherit from any of the out of the box formatters: https://logger.rocketjob.io/customize.html
Issue # (if available)
Related to #149 (but does NOT fix the issue - it does not make it possible to modify the message, simply make it slightly more descriptive in rails controller logs).
For context, here's how SemanticLogger logs are listed in Datadog by default:
(sure: I can also filter by log name or even add a column displaying the log name - but as it is the message isn't very helpful.)
Description of changes
Add controller name to Rails controller logs, so instead of
Completed #show
We might have instead:
Completed UsersController#show