Closed chall8908 closed 2 months ago
👋 @chall8908, thanks for this issue report.
Could you provide the relevant Rails log configuration you use (Lograge configuration, any /config\..*log.*/
related Rails configuration) and the Rails version and Lograge you are running?
One possibility is that the problem is a mix of specific versions of Rails, Lograge and ddtrace combined.
Hi @marcotc 👋🏻 I'm noticing this as well. With Datadog v1.1.0 (we upgraded recently and directly from v0.54.2) and our Lograge integration, our logs have prepended the Datadog log text before the json format which does include the Datadog tracing info.
[dd.env=production dd.service=my-app dd.version=123 dd.trace_id=123 dd.span_id=123] {"method":"POST","path":"/","format":"html","controller":"SiteController","action":"index","status":200,"duration":90.02,"view":18.85,"db":25.61,"dd":{"trace_id":"123","span_id":"123","env":"production","service":"my-app","version":"123"},"ddsource":"ruby","time":728707.869930716,"params":{},"request_id":"123"}
Before replacing the info in the log shared above, the trace and span ids were a match in both text and json formats.
We are using lograge v0.12.0 (latest), ddtrace v1.1.0 (latest) and rails v6.1.6.
@marcotc we are actually overriding the default logger whereas with what @chall8908 wrote it seems they aren't but that is still resulting in the same output issue.
For Lograge config:
Rails.application.configure do
config.lograge.enabled = true
# Set the default log formatter but only if we have Lograge
# enabled since we are using the Lograge JSON formatter.
if config.lograge.enabled
config.log_formatter = Lograge::Formatters::Json.new
config.lograge.formatter = config.log_formatter
end
# Add our own custom data and Lograge will take care of merging this with
# a base set. Do not merge `event.payload` (only merge explicit values)
# as that contains a large object from ActionDispatch.
config.lograge.custom_options = ->(event) do
{
time: event.time,
params: event.payload[:params].except("controller", "action", "format")
}.merge(event.payload[:custom_payload] || {})
end
# A hook to access controller methods so we can log common request info.
config.lograge.custom_payload do |controller|
{
request_id: controller.request.uuid,
user_id: controller.current_user.try(:id)
}.compact
end
end
For Rails logging:
# Include generic and useful information about system operation, but avoid logging too much
# information to avoid inadvertent exposure of personally identifiable information (PII).
config.log_level = ENVied.LOG_LEVEL
# Prepend all log lines with the following tags.
# config.log_tags = [ :request_id ]
# Log disallowed deprecations.
config.active_support.disallowed_deprecation = :log
# Tell Active Support which deprecation messages to disallow.
config.active_support.disallowed_deprecation_warnings = []
# Use default logging formatter so that PID and timestamp are not suppressed.
# config.log_formatter = ::Logger::Formatter.new
# Use a different logger for distributed setups.
# require "syslog/logger"
# config.logger = ActiveSupport::TaggedLogging.new(Syslog::Logger.new 'app-name')
if ENVied.RAILS_LOG_TO_STDOUT
config.logger = ActiveSupport::TaggedLogging.new(ActiveSupport::Logger.new(STDOUT))
end
# Log CSRF failures
config.action_controller.log_warning_on_csrf_failure = true
@marcotc sorry for leaving this for so long. We ended up pivoting off Lograge entirely and I got pulled away to other projects.
@javierjulio has the right of it, though. We were using Lograge more-or-less out-of-the-box. That particular project is on Rails 6 when I was testing it. Before deciding to ditch Lograge entirely, I'd pared down our configuration to just enabling Lograge and setting the JSON formatter. No other configuration.
Since Lograge doesn't change the Rails.logger
by default, it usually remains as an ActiveSupport::TaggedLogging
instance which triggers dd-trace to set log_tags
which causes the problem.
I think swapping the add_logger
call from before_initialize
to after_initialize
and actually checking if Lograge is enabled should fix the problem, but I'm not sure if that would cause downstream problems.
Hey :wave:
I was getting the same error as @javierjulio in my logs using the same stack. I'm not sure about the side effects but I've got a fix by disabling the log injection before rails initialization. I've added Datadog.configuration.tracing.log_injection = false
in my config/environment.rb
before Rails.application.initialize!
, and the datadog tracing prefix was removed from my JSON logs.
Be advised: I'm sure about the side-effects of this solution :smile:
EDIT: thank you @chall8908 for pointing out a way
I can confirm the solution used by @eduardohertz, in our case we put the configuration in the config/environment/*.rb
files, which are loaded at the right time.
_Before that we were tried to remove the DD tagger manually with #Rails.configuration.log_tags.reject! { _1.source_location.first.match? 'lib/datadog/tracing' }
but it didn't look pretty._
@chall8908 since you mentioned Lograge was removed, may I ask what you replaced it with and is that new thing still doing JSON formatting for logs? I'd be open to changing ours but I'm not familiar with another alternative.
@marcotc we haven't been able to upgrade from 0.54.2 due to this bug where the logs include both JSON and text output because of ddtrace. Is there any chance of it being resolved?
@javierjulio we switched to Semantic Logger which does still do JSON logging (among other things).
+1 to this issue. I have several teams that are running into this or will hit it in the near future and the docs don't offer a workaround.
👋 @too-gee Thanks for reporting, I will try to reproduce it and address it.
@TonyCTHsu thank you!
@chall8908 @javierjulio 👋 I want to give you guys a quick update from my side.
I was able to reproduce with lograge
, I want to try out with semantic_logger
later.
Question: Are you using auto instrument? require: 'ddtrace/auto_instrument'
in Gemfile
?
@TonyCTHsu thanks! No, we are not using auto instrument.
@TonyCTHsu our projects are using auto instrumentation.
I'd have to double check, but I recall that semantic_logger
didn't have this issue because it overrides the Rails logger with its own logger, bypassing the problem code.
@TonyCTHsu We see the same issue with lograge
, we use auto_instrument
in our Rails projects.
@chall8908 @artrybalko @javierjulio , I realized that auto instrumentation with a Rails app that would enable log injection for both lograge
and Rails' ActiveSupport::TaggedLogging
, which is causing the double insertion mentioned above.
Currently, the injection for ActiveSupport::TaggedLogging
is only controlled by config.log_injection
, hence it is a bit cumbersome to only activate Lograge
without activate ActiveSupport::TaggedLogging
injection.
Workaround: Configure your application explicitly with a logger what is not a ActiveSupport::TaggedLogging
Replace
config.logger = ActiveSupport::TaggedLogging.new(logger)
with
config.logger = logger
Noted that Rails is using ActiveSupport::TaggedLogging
by default without any configuration
This is similar to the reason that semantic logger does not observed double insertion because semantic logger replaces the logger instance. In the future, we will be introducing a configuration option explicitly for ActiveSupport::TaggedLogging
.
@TonyCTHsu Thanks for the feedback! We are switching to semantic logger as a trial. This issue wasn't the main consideration but it pushed it over the line.
Sorry for the wait everyone.
I did some investigation on this issue this week and found out that lograge
is not compatible with ActiveSupport::TaggedLogging
when config.log_tags
are set. This is especially problematic when JSON output format is configured for lograge
.
There are a couple open issues in the lograge
repository about this issue: https://github.com/roidrage/lograge/issues/233#issuecomment-404336057, https://github.com/roidrage/lograge/issues/255
There is no good immediate solution for this issue:
semantic_logger
instead of lograge
. Semantic Logger integrates with Rails named tags natively. There's no loss in observability for this solution.ActiveSupport::TaggedLogging
with ActiveSupport::Logger
:
config.logger = ActiveSupport::Logger.new(STDOUT)
config.active_job.logger = ActiveSupport::Logger.new(STDOUT)
All lograge
log lines will have the correct JSON format. The downside is that log lines that are not handled by lograge
, for example simple Rails.logger.*
calls, will not have trace correlation information.
Looking at internals of both semantic_logger
and lograge
, it looks at me that semantic_logger
it's better equipped to handle modern versions of Rails. I would recommend using semantic_logger
instead of lograge
if the native ActiveSupport::TaggedLogging
is not sufficient.
@marcotc thank you. We removed tagged logging as it's not something we use. It's actually better for us to provide our logs in JSON format for easy filtering. As you noted the Datadog trace correlation information is not included. Are we able to include that manually in a logger call in a safe manner?
Hey, I also just wanted to follow up and see if this is also still occurring with the newest release of Datadog? We're on v2.2.0
.
We're looking at adding the extra needed steps to the docs in #3812, let us know if that works!
We added an explicit message in code warning the user when this happens (and how to address it) in #3839 as well as in our public documentation #3812.
This comment above has the investigation write-up and alternatives, and explains why the issue happens between Lograge and Rails and cannot be addressed in dd-trace-rb
.
2.3.0
has been released.
I've come across this discussion since upgrading to 2.3.0 and seeing warning messages polluting our startup logs.
We've been using TaggedLogging outputting in JSON in production for quite a while now. The implementation of our extension to ActiveSupport::TaggedLogging in order to support this has been recently extracted to be public: https://github.com/armstrjare/rails-json-tagged-logging
It would be great to disable these warning messages somehow!
Here is the relevant parts of our lograge initialiser that merges tags and user info into the log output, and ensures clean log output. The majority of this is for adding additional tags etc to the JSON output and tweaking the message formatting:
Rails.application.configure do
config.lograge.enabled = true
# Use a fresh logger to separate to Lograge to avoid Tags, etc.
config.lograge.logger = Rails.logger.dup.tap { |logger| logger.formatter = ActiveSupport::Logger::SimpleFormatter.new }
config.lograge.formatter = Lograge::Formatters::Json.new
config.lograge.keep_original_rails_log = Rails.env.development? || Rails.env.test?
config.lograge.ignore_actions = ['Rails::HealthController#show', 'ActiveStorage::BlobsController#show']
custom_options = config.lograge.custom_options
# This executes on each log event to tweak the output, including
# adding relevant the tags and usr info to the JSON output.
config.lograge.custom_options = -> event {
# Get the original options before overriding
options = if custom_options.respond_to?(:call)
custom_options.call(event)
else
custom_options
end
# Get our standard set of request tags
formatter = case Rails.logger
when ActiveSupport::BroadcastLogger
Rails.logger.broadcasts.first.formatter
else
Rails.logger.formatter
end
current_tags = formatter.respond_to?(:current_tags) ? formatter.current_tags : []
tags = LogTagging.collapse_tags(current_tags)
if usr_tags = event.payload[:usr]
tags.deep_merge!(usr: usr_tags)
end
r = event.payload
message = "Completed "
message << "#{r[:method]} "
message << "#{r[:controller]}##{r[:action]} "
message << "#{r[:status]} #{Rack::Utils::HTTP_STATUS_CODES[r[:status]]} "
message << "in #{event.duration.round}ms "
message << "at #{r[:path]}"
# Combine and include extra options
(options || {}).merge(tags).merge(
params: event.payload[:params].except(*%w(controller action format)),
message: message
)
}
unless Rails.env.development?
config.log_tags = config.log_tags.to_a + [
LogTagging::RequestId,
LogTagging::RemoteIp,
LogTagging::ClientUser
]
end
end
The current implementation of the Rails integration causes log correlation information to be added twice to the logger when using Lograge. This breaks log parsing in Datadog if Lograge is using the JSON formatter.
I'm currently attempting to work around this by setting
Rails.configuration.log_tags = []
ininitializers/datadog.rb
.As far as I can tell, this is likely going to be a problem in any Rails project that doesn't override the default logger when using Lograge (which doesn't modify the default logger) and using the JSON formatter.
I'm not sure if it's possible to simply delay modifying
Rails.configuration.log_tags
untilafter_initialize
and still have everything function correctly. If nothing else, a mention in the README about this potential issue would save other people the head-scratching.