Log correlationedit
Trace/log correlation can be set up in three different ways.
Rails TaggedLoggingedit
Rails applications configured with an ActiveSupport::TaggedLogging logger can append the correlation IDs to log output.
For example in your config/environments/production.rb file, add the following:
config.log_tags = [ :request_id, proc { ElasticAPM.log_ids } ]
# Logs will then include the correlation IDs:
#
# [transaction.id=c1ae84c8642891eb trace.id=b899fc7915e801b7558e336e4952bafe] Started GET "/" for 127.0.0.1 at 2019-09-16 11:28:46 +0200
# [transaction.id=c1ae84c8642891eb trace.id=b899fc7915e801b7558e336e4952bafe] Processing by ApplicationController#index as HTML
# [transaction.id=c1ae84c8642891eb trace.id=b899fc7915e801b7558e336e4952bafe] Rendering text template
# [transaction.id=c1ae84c8642891eb trace.id=b899fc7915e801b7558e336e4952bafe] Rendered text template (Duration: 0.1ms | Allocations: 17)
# [transaction.id=c1ae84c8642891eb trace.id=b899fc7915e801b7558e336e4952bafe] Completed 200 OK in 1ms (Views: 0.4ms | Allocations: 171)
Note: Because of the order in which Rails computes the tags for logs and executes the request, the span id might not be included.
Consider using Lograge instead, as the timing of its hooks allow the span id to be captured in logs.
Logrageedit
With lograge enabled and set up in your Rails application, modify the custom_options block in the Rails environment
configuration file. The returned Hash will be included in the structured Lograge logs.
config.lograge.custom_options = lambda do |event|
ElasticAPM.log_ids do |transaction_id, span_id, trace_id|
{ :'transaction.id' => transaction_id,
:'span.id' => span_id,
:'trace.id' => trace_id }
end
end
# Logs will then include the correlation IDs:
#
# I, [2019-09-16T11:59:05.439602 #8674] INFO -- : method=GET path=/ format=html controller=ApplicationController action=index status=200 duration=0.36 view=0.20 transaction.id=56a9186a9257aa08 span.id=8e84a786ab0abbb2 trace.id=1bbab8ac4c7c9584f53eb882ff0dfdd8
You can also nest the ids in a separate document as in the following example:
config.lograge.custom_options = lambda do |event|
ElasticAPM.log_ids do |transaction_id, span_id, trace_id|
{ elastic_apm: { :'transaction.id' => transaction_id,
:'span.id' => span_id,
:'trace.id' => trace_id } }
end
end
# Logs will then include the correlation IDs in a separate document:
#
# I, [2019-09-16T13:39:35.962603 #9327] INFO -- : method=GET path=/ format=html controller=ApplicationController action=index status=200 duration=0.37 view=0.20 elastic_apm={:transaction_id=>"2fb84f5d0c48a296", :span_id=>"2e5c5a7c85f83be7", :trace_id=>"43e1941c4a6fff343a4e018ff7b92000"}
Manually formatting logsedit
You can access the correlation ids directly and add them through the log formatter.
require 'elastic_apm'
require 'logger'
logger = Logger.new(STDOUT)
logger.progname = 'TestRubyApp'
logger.formatter = proc do |severity, datetime, progname, msg|
"[#{datetime}][#{progname}][#{severity}][#{ElasticAPM.log_ids}] #{msg}\n"
end
# Logs will then include the correlation IDs:
#
# [2019-09-16 11:54:59 +0200][RailsTestApp][INFO][transaction.id=3b92edcccc0a6d1e trace.id=1275686e35de91f776557637e799651e] Started GET "/" for 127.0.0.1 at 2019-09-16 11:54:59 +0200
# [2019-09-16 11:54:59 +0200][RailsTestApp][INFO][transaction.id=3b92edcccc0a6d1e trace.id=1275686e35de91f776557637e799651e] Processing by ApplicationController#index as HTML
# [2019-09-16 11:54:59 +0200][RailsTestApp][INFO][transaction.id=3b92edcccc0a6d1e span.id=3bde4e9c85ab359c trace.id=1275686e35de91f776557637e799651e] Rendering text template
# [2019-09-16 11:54:59 +0200][RailsTestApp][INFO][transaction.id=3b92edcccc0a6d1e span.id=f3d7e32f176d4c93 trace.id=1275686e35de91f776557637e799651e] Rendered text template (Duration: 0.1ms | Allocations: 17)
# [2019-09-16 11:54:59 +0200][RailsTestApp][INFO][transaction.id=3b92edcccc0a6d1e span.id=3bde4e9c85ab359c trace.id=1275686e35de91f776557637e799651e] Completed 200 OK in 1ms (Views: 0.3ms | Allocations: 187)