diff --git a/benchmarks/di_instrument.rb b/benchmarks/di_instrument.rb index 58d3b1f78cc..1872153df9e 100644 --- a/benchmarks/di_instrument.rb +++ b/benchmarks/di_instrument.rb @@ -43,6 +43,11 @@ # Need to require datadog/di explicitly because dynamic instrumentation is not # currently integrated into the Ruby tracer due to being under development. require 'datadog/di' +begin + require 'datadog/di/proc_responder' +rescue LoadError + # Old tree +end class DIInstrumentBenchmark class Target @@ -106,9 +111,15 @@ def run_benchmark calls = 0 probe = Datadog::DI::Probe.new(id: 1, type: :log, type_name: 'DIInstrumentBenchmark::Target', method_name: 'test_method') - rv = instrumenter.hook_method(probe) do + executed_proc = lambda do |context| calls += 1 end + if defined?(Datadog::DI::ProcResponder) + responder = Datadog::DI::ProcResponder.new(executed_proc) + rv = instrumenter.hook_method(probe, responder) + else + rv = instrumenter.hook_method(probe, &executed_proc) + end unless rv raise "Method probe was not successfully installed" end @@ -149,8 +160,11 @@ def run_benchmark calls = 0 probe = Datadog::DI::Probe.new(id: 1, type: :log, file: file, line_no: line + 1) - rv = instrumenter.hook_line(probe) do - calls += 1 + if defined?(Datadog::DI::ProcResponder) + responder = Datadog::DI::ProcResponder.new(executed_proc) + rv = instrumenter.hook_line(probe, responder) + else + rv = instrumenter.hook_line(probe, &executed_proc) end unless rv raise "Line probe (in method) was not successfully installed" @@ -198,8 +212,10 @@ def run_benchmark calls = 0 probe = Datadog::DI::Probe.new(id: 1, type: :log, file: targeted_file, line_no: targeted_line + 1) - rv = instrumenter.hook_line(probe) do - calls += 1 + rv = if defined?(Datadog::DI::ProcResponder) + instrumenter.hook_line(probe, responder) + else + instrumenter.hook_line(probe, &executed_proc) end unless rv raise "Line probe (targeted) was not successfully installed" diff --git a/lib/datadog/di/instrumenter.rb b/lib/datadog/di/instrumenter.rb index 87a839a3889..17e6477e142 100644 --- a/lib/datadog/di/instrumenter.rb +++ b/lib/datadog/di/instrumenter.rb @@ -89,11 +89,7 @@ def initialize(settings, serializer, logger, code_tracker: nil, telemetry: nil) # from the method but from outside of the method). Location = Struct.new(:path, :lineno, :label) - def hook_method(probe, &block) - unless block - raise ArgumentError, 'block is required' - end - + def hook_method(probe, responder) lock.synchronize do if probe.instrumentation_module # Already instrumented, warn? @@ -130,10 +126,34 @@ def hook_method(probe, &block) caller_locations: caller_locations, ) continue = condition.satisfied?(context) - rescue - raise if settings.dynamic_instrumentation.internal.propagate_all_exceptions + rescue => exc + # Evaluation error exception can be raised for "expected" + # errors, we probably need another setting to control whether + # these exceptions are propagated. + raise if settings.dynamic_instrumentation.internal.propagate_all_exceptions && + !exc.is_a?(DI::Error::ExpressionEvaluationError) + + if context + # We want to report evaluation errors for conditions + # as probe snapshots. However, if we failed to create + # the context, we won't be able to report anything as + # the probe notifier builder requires a context. + begin + responder.probe_condition_evaluation_failed_callback(context, exc) + rescue + raise if settings.dynamic_instrumentation.internal.propagate_all_exceptions + + # TODO log / report via telemetry? + end + else + _ = 42 # stop standard from wrecking this code + + raise if settings.dynamic_instrumentation.internal.propagate_all_exceptions + + # TODO log / report via telemetry? + # If execution gets here, there is probably a bug in the tracer. + end - # TODO log / report via telemetry? continue = false end end @@ -195,8 +215,7 @@ def hook_method(probe, &block) caller_locations: caller_locs, return_value: rv, duration: duration, exception: exc,) - # & is to stop steep complaints, block is always present here. - block&.call(context) + responder.probe_executed_callback(context) if exc raise exc else @@ -258,11 +277,7 @@ def unhook_method(probe) # not for eval'd code, unless the eval'd code is associated with # a file name and client invokes this method with the correct # file name for the eval'd code. - def hook_line(probe, &block) - unless block - raise ArgumentError, 'No block given to hook_line' - end - + def hook_line(probe, responder) lock.synchronize do if probe.instrumentation_trace_point # Already instrumented, warn? @@ -367,14 +382,44 @@ def hook_line(probe, &block) if continue if condition = probe.condition - context = Context.new( - locals: Instrumenter.get_local_variables(tp), - target_self: tp.self, - probe: probe, settings: settings, serializer: serializer, - path: tp.path, - caller_locations: caller_locations, - ) - continue = condition.satisfied?(context) + begin + context = Context.new( + locals: Instrumenter.get_local_variables(tp), + target_self: tp.self, + probe: probe, settings: settings, serializer: serializer, + path: tp.path, + caller_locations: caller_locations, + ) + continue = condition.satisfied?(context) + rescue => exc + # Evaluation error exception can be raised for "expected" + # errors, we probably need another setting to control whether + # these exceptions are propagated. + raise if settings.dynamic_instrumentation.internal.propagate_all_exceptions && + !exc.is_a?(DI::Error::ExpressionEvaluationError) + + continue = false + if context + # We want to report evaluation errors for conditions + # as probe snapshots. However, if we failed to create + # the context, we won't be able to report anything as + # the probe notifier builder requires a context. + begin + responder.probe_condition_evaluation_failed_callback(context, condition, exc) + rescue + raise if settings.dynamic_instrumentation.internal.propagate_all_exceptions + + # TODO log / report via telemetry? + end + else + _ = 42 # stop standard from wrecking this code + + raise if settings.dynamic_instrumentation.internal.propagate_all_exceptions + + # TODO log / report via telemetry? + # If execution gets here, there is probably a bug in the tracer. + end + end end end @@ -393,8 +438,7 @@ def hook_line(probe, &block) caller_locations: caller_locations, ) - # & is to stop steep complaints, block is always present here. - block&.call(context) + responder.probe_executed_callback(context) end rescue => exc raise if settings.dynamic_instrumentation.internal.propagate_all_exceptions @@ -443,11 +487,11 @@ def unhook_line(probe) end end - def hook(probe, &block) + def hook(probe, responder) if probe.method? - hook_method(probe, &block) + hook_method(probe, responder) elsif probe.line? - hook_line(probe, &block) + hook_line(probe, responder) else # TODO add test coverage for this path logger.debug { "di: unknown probe type to hook: #{probe}" } diff --git a/lib/datadog/di/probe.rb b/lib/datadog/di/probe.rb index c04e7a59d2d..62c90eb03cd 100644 --- a/lib/datadog/di/probe.rb +++ b/lib/datadog/di/probe.rb @@ -86,6 +86,16 @@ def initialize(id:, type:, @rate_limit = rate_limit || (@capture_snapshot ? 1 : 5000) @rate_limiter = Datadog::Core::TokenBucket.new(@rate_limit) + # At most one report per second. + # We create the rate limiter here even though it may never be used, + # to avoid having to synchronize the creation since method probes + # can be executed on multiple threads concurrently (even if line + # probes are never executed concurrently since those are done in a + # trace point). + if condition + @condition_evaluation_failed_rate_limiter = Datadog::Core::TokenBucket.new(1) + end + @emitting_notified = false end @@ -115,6 +125,16 @@ def initialize(id:, type:, # Rate limiter object. For internal DI use only. attr_reader :rate_limiter + # Rate limiter object for sending snapshots with evaluation errors + # for when probe condition evaluation fails. + # This rate limit is separate from the "base" rate limit for the probe + # because when the condition evaluation succeeds we want the "base" + # rate limit applied, not tainted by any evaluation errors + # (for example, the condition can be highly selective, and when it + # does not hold the evaluation may fail - we don't want to use up the + # probe rate limit for the errors). + attr_reader :condition_evaluation_failed_rate_limiter + def capture_snapshot? @capture_snapshot end diff --git a/lib/datadog/di/probe_manager.rb b/lib/datadog/di/probe_manager.rb index db5327b7cca..392d3253471 100644 --- a/lib/datadog/di/probe_manager.rb +++ b/lib/datadog/di/probe_manager.rb @@ -101,7 +101,7 @@ def add_probe(probe) end begin - instrumenter.hook(probe, &method(:probe_executed_callback)) + instrumenter.hook(probe, self) @installed_probes[probe.id] = probe payload = probe_notification_builder.build_installed(probe) @@ -184,7 +184,7 @@ def remove_other_probes(probe_ids) begin # TODO is it OK to hook from trace point handler? # TODO the class is now defined, but can hooking still fail? - instrumenter.hook(probe, &method(:probe_executed_callback)) + instrumenter.hook(probe, self) @pending_probes.delete(probe.id) break rescue Error::DITargetNotDefined @@ -242,6 +242,14 @@ def probe_executed_callback(context) probe_notifier_worker.add_snapshot(payload) end + def probe_condition_evaluation_failed_callback(context, expr, exc) + probe = context.probe + if probe.condition_evaluation_failed_rate_limiter&.allow? + payload = probe_notification_builder.build_condition_evaluation_failed(context, expr, exc) + probe_notifier_worker.add_snapshot(payload) + end + end + # Class/module definition trace point (:end type). # Used to install hooks when the target classes/modules aren't yet # defined when the hook request is received. diff --git a/lib/datadog/di/probe_notification_builder.rb b/lib/datadog/di/probe_notification_builder.rb index fac71b81cc0..bd4bc623dd7 100644 --- a/lib/datadog/di/probe_notification_builder.rb +++ b/lib/datadog/di/probe_notification_builder.rb @@ -87,6 +87,32 @@ def build_snapshot(context) end end + message = nil + evaluation_errors = [] + if segments = probe.template_segments + message, evaluation_errors = evaluate_template(segments, context) + end + build_snapshot_base(context, + evaluation_errors: evaluation_errors, message: message, + captures: captures) + end + + def build_condition_evaluation_failed(context, expression, exception) + error = { + message: "#{exception.class}: #{exception}", + expr: expression.dsl_expr, + } + build_snapshot_base(context, evaluation_errors: [error]) + end + + private + + def build_snapshot_base(context, evaluation_errors: [], captures: nil, message: nil) + probe = context.probe + + timestamp = timestamp_now + duration = context.duration + location = if probe.line? { file: context.path, @@ -103,13 +129,6 @@ def build_snapshot(context) format_caller_locations(caller_locations) end - timestamp = timestamp_now - message = nil - evaluation_errors = [] - if segments = probe.template_segments - message, evaluation_errors = evaluate_template(segments, context) - end - duration = context.duration { service: settings.service, "debugger.snapshot": { @@ -132,7 +151,7 @@ def build_snapshot(context) host: nil, logger: { name: probe.file, - method: probe.method_name || 'no_method', + method: probe.method_name, thread_name: Thread.current.name, # Dynamic instrumentation currently does not need thread_id for # anything. It can be sent if a customer requests it at which point @@ -150,8 +169,6 @@ def build_snapshot(context) } end - private - def build_status(probe, message:, status:) { service: settings.service, diff --git a/lib/datadog/di/proc_responder.rb b/lib/datadog/di/proc_responder.rb new file mode 100644 index 00000000000..d162f2c0f33 --- /dev/null +++ b/lib/datadog/di/proc_responder.rb @@ -0,0 +1,32 @@ +# frozen_string_literal: true + +module Datadog + module DI + # An adapter to convert procs to responders. + # + # Used in test suite and benchmarks. + # + # @api private + class ProcResponder + def initialize(executed_proc, failed_proc = nil) + @executed_proc = executed_proc + @failed_proc = failed_proc + end + + attr_reader :executed_proc + attr_reader :failed_proc + + def probe_executed_callback(context) + executed_proc.call(context) + end + + def probe_condition_evaluation_failed_callback(context, exc) + if failed_proc.nil? + raise NotImplementedError, "Failed proc not provided" + end + + failed_proc.call(context, exc) + end + end + end +end diff --git a/sig/datadog/di/instrumenter.rbs b/sig/datadog/di/instrumenter.rbs index bae12f65075..ad750db14b5 100644 --- a/sig/datadog/di/instrumenter.rbs +++ b/sig/datadog/di/instrumenter.rbs @@ -33,14 +33,14 @@ module Datadog attr_reader telemetry: Core::Telemetry::Component? - def hook_method: (Probe probe) ?{ (?) -> untyped } -> void + def hook_method: (Probe probe, untyped responder) -> void def unhook_method: (Probe probe) -> void - def hook_line: (Probe probe) ?{ (?) -> untyped } -> void + def hook_line: (Probe probe, untyped responder) -> void def unhook_line: (Probe probe) -> void - def hook: (Probe probe) { (?) -> untyped } -> void + def hook: (Probe probe, untyped responder) -> void def unhook: (Probe probe) -> void diff --git a/sig/datadog/di/probe_manager.rbs b/sig/datadog/di/probe_manager.rbs index 3fba0223e2e..aa9fd31b916 100644 --- a/sig/datadog/di/probe_manager.rbs +++ b/sig/datadog/di/probe_manager.rbs @@ -45,11 +45,6 @@ module Datadog def pending_probes: () -> untyped def failed_probes: () -> untyped def add_probe: (untyped probe) -> untyped - - private - def do_add_probe: (untyped probe) -> untyped - - public def remove_other_probes: (untyped probe_ids) -> untyped private @@ -57,7 +52,9 @@ module Datadog public def install_pending_line_probes: (untyped path) -> untyped - def probe_executed_callback: (Context context) -> untyped + def probe_executed_callback: (untyped context) -> untyped + + def probe_condition_evaluation_failed_callback: (untyped context, untyped expr, untyped exc) -> untyped attr_reader definition_trace_point: untyped end end diff --git a/sig/datadog/di/probe_notification_builder.rbs b/sig/datadog/di/probe_notification_builder.rbs index e05a7703aeb..30ec3871bcd 100644 --- a/sig/datadog/di/probe_notification_builder.rbs +++ b/sig/datadog/di/probe_notification_builder.rbs @@ -22,6 +22,9 @@ module Datadog def build_executed: (Context context) -> Hash[Symbol,untyped] def build_snapshot: (Context context) -> Hash[Symbol,untyped] + def build_snapshot_base: (Context context, ?evaluation_errors: Array[untyped]?, ?captures: untyped?, ?message: String?) -> Hash[Symbol,untyped] + + def build_condition_evaluation_failed: (Context context, untyped expr, untyped exception) -> Hash[Symbol,untyped] def build_status: (Probe probe, message: untyped, status: untyped) -> Hash[Symbol,untyped] diff --git a/sig/datadog/di/proc_responder.rbs b/sig/datadog/di/proc_responder.rbs new file mode 100644 index 00000000000..f99c0ac1e67 --- /dev/null +++ b/sig/datadog/di/proc_responder.rbs @@ -0,0 +1,19 @@ +module Datadog + module DI + class ProcResponder + @executed_proc: untyped + + @failed_proc: untyped + + def initialize: (untyped executed_proc, ?untyped? failed_proc) -> void + + attr_reader executed_proc: untyped + + attr_reader failed_proc: untyped + + def probe_executed_callback: (untyped context) -> untyped + + def probe_condition_evaluation_failed_callback: (untyped context, untyped exc) -> untyped + end + end +end diff --git a/spec/datadog/di/instrumenter_spec.rb b/spec/datadog/di/instrumenter_spec.rb index 0942fce5e27..b847409b4a2 100644 --- a/spec/datadog/di/instrumenter_spec.rb +++ b/spec/datadog/di/instrumenter_spec.rb @@ -3,6 +3,7 @@ require 'datadog/di/code_tracker' require 'datadog/di/serializer' require 'datadog/di/probe' +require 'datadog/di/proc_responder' require_relative 'hook_line' require_relative 'hook_method' require 'logger' @@ -59,6 +60,16 @@ Datadog::DI::Probe.new(**base_probe_args.merge(probe_args)) end + def hook_method(probe, &block) + responder = Datadog::DI::ProcResponder.new(block) + instrumenter.hook_method(probe, responder) + end + + def hook_line(probe, &block) + responder = Datadog::DI::ProcResponder.new(block) + instrumenter.hook_line(probe, responder) + end + shared_context 'with code tracking' do let!(:code_tracker) do Datadog::DI::CodeTracker.new.tap do |tracker| @@ -82,7 +93,7 @@ end it 'invokes callback' do - instrumenter.hook_method(probe) do |payload| + hook_method(probe) do |payload| observed_calls << payload end @@ -103,7 +114,7 @@ end it 'invokes callback' do - instrumenter.hook_method(probe) do |payload| + hook_method(probe) do |payload| observed_calls << payload end @@ -124,7 +135,7 @@ let(:rate_limit) { 0 } it 'does not invoke callback but invokes target method with block' do - instrumenter.hook_method(probe) do |payload| + hook_method(probe) do |payload| observed_calls << payload end @@ -150,7 +161,7 @@ end it 'invokes callback' do - instrumenter.hook_method(probe) do |payload| + hook_method(probe) do |payload| observed_calls << payload end @@ -171,7 +182,7 @@ let(:rate_limit) { 0 } it 'does not invoke callback but invokes target method with block' do - instrumenter.hook_method(probe) do |payload| + hook_method(probe) do |payload| observed_calls << payload end @@ -193,7 +204,7 @@ end it 'invokes callback' do - instrumenter.hook_method(probe) do |payload| + hook_method(probe) do |payload| observed_calls << payload end @@ -214,7 +225,7 @@ let(:rate_limit) { 0 } it 'does not invoke callback but invokes target method with block' do - instrumenter.hook_method(probe) do |payload| + hook_method(probe) do |payload| observed_calls << payload end @@ -236,7 +247,7 @@ end it 'invokes callback' do - instrumenter.hook_method(probe) do |payload| + hook_method(probe) do |payload| observed_calls << payload end @@ -257,7 +268,7 @@ let(:rate_limit) { 0 } it 'does not invoke callback but invokes target method with block' do - instrumenter.hook_method(probe) do |payload| + hook_method(probe) do |payload| observed_calls << payload end @@ -289,7 +300,7 @@ shared_examples 'does not invoke callback but invokes target method' do it 'does not invoke callback but invokes target method' do - instrumenter.hook_method(probe) do |payload| + hook_method(probe) do |payload| observed_calls << payload end @@ -310,7 +321,7 @@ end it 'captures instance variables' do - instrumenter.hook_method(probe) do |payload| + hook_method(probe) do |payload| observed_calls << payload end @@ -339,7 +350,7 @@ end it 'invokes callback' do - instrumenter.hook_method(probe) do |payload| + hook_method(probe) do |payload| observed_calls << payload end @@ -365,7 +376,7 @@ shared_examples 'invokes callback and captures parameters' do it 'invokes callback and captures parameters' do - instrumenter.hook_method(probe) do |payload| + hook_method(probe) do |payload| observed_calls << payload end @@ -393,7 +404,7 @@ end it 'captures instance variables in addition to parameters' do - instrumenter.hook_method(probe) do |payload| + hook_method(probe) do |payload| observed_calls << payload end @@ -455,7 +466,7 @@ shared_examples 'invokes callback and captures parameters' do it 'invokes callback and captures parameters' do - instrumenter.hook_method(probe) do |payload| + hook_method(probe) do |payload| observed_calls << payload end @@ -507,7 +518,7 @@ end it 'captures instance variables in addition to kwargs' do - instrumenter.hook_method(probe) do |payload| + hook_method(probe) do |payload| observed_calls << payload end @@ -545,7 +556,7 @@ shared_examples 'invokes callback and captures parameters' do it 'invokes callback and captures parameters' do - instrumenter.hook_method(probe) do |payload| + hook_method(probe) do |payload| observed_calls << payload end @@ -597,7 +608,7 @@ shared_examples 'invokes callback and captures parameters' do it 'invokes callback and captures parameters' do - instrumenter.hook_method(probe) do |payload| + hook_method(probe) do |payload| observed_calls << payload end @@ -652,7 +663,7 @@ context 'when there is also a positional argument' do shared_examples 'invokes callback and captures parameters' do it 'invokes callback and captures parameters' do - instrumenter.hook_method(probe) do |payload| + hook_method(probe) do |payload| observed_calls << payload end @@ -713,7 +724,7 @@ end it 'invokes callback' do - instrumenter.hook_method(probe) do |payload| + hook_method(probe) do |payload| observed_calls << payload end @@ -754,11 +765,11 @@ # We do not currently de-duplicate. it 'invokes callback twice' do - instrumenter.hook_method(probe) do |payload| + hook_method(probe) do |payload| observed_calls << payload end - instrumenter.hook_method(probe2) do |payload| + hook_method(probe2) do |payload| observed_calls << payload end @@ -781,7 +792,7 @@ it 'raises DITargetNotDefined' do expect do - instrumenter.hook_method(probe) do |payload| + hook_method(probe) do |payload| end end.to raise_error(Datadog::DI::Error::DITargetNotDefined) end @@ -806,7 +817,7 @@ end let(:payload) do - instrumenter.hook_method(probe) do |payload| + hook_method(probe) do |payload| observed_calls << payload end @@ -843,7 +854,7 @@ end it 'invokes callback for every method invocation' do - instrumenter.hook_method(probe) do |payload| + hook_method(probe) do |payload| observed_calls << payload end @@ -880,7 +891,7 @@ end it 'does not invoke callback' do - instrumenter.hook_method(probe) do |payload| + hook_method(probe) do |payload| observed_calls << payload end @@ -907,7 +918,7 @@ shared_examples 'reports the call' do it 'reports the call' do - instrumenter.hook_method(probe) do |payload| + hook_method(probe) do |payload| observed_calls << payload end @@ -919,7 +930,7 @@ shared_examples 'does not report the call' do it 'does not report the call' do - instrumenter.hook_method(probe) do |payload| + hook_method(probe) do |payload| observed_calls << payload end @@ -929,6 +940,18 @@ end end + shared_examples 'does not report the call and reports evaluation failure' do + let(:responder) { double('responder') } + + it 'does not report the call and reports evaluation failure' do + expect(responder).not_to receive(:probe_executed_callback) + expect(responder).to receive(:probe_condition_evaluation_failed_callback) + instrumenter.hook_method(probe, responder) + + target_call + end + end + context 'when condition is on positional argument' do context 'when condition is met' do let(:condition) do @@ -989,7 +1012,7 @@ ) end - include_examples 'does not report the call' + include_examples 'does not report the call and reports evaluation failure' end end end @@ -1015,7 +1038,7 @@ it 'invokes the instrumentation every time' do expect_any_instance_of(TracePoint).to receive(:enable).and_call_original - instrumenter.hook_line(probe) do |payload| + hook_line(probe) do |payload| observed_calls << payload end @@ -1030,25 +1053,6 @@ end end - context 'when called without a block' do - let(:probe) do - instance_double(Datadog::DI::Probe) - end - - after do - # Needed for the cleanup unhook call. - allow(probe).to receive(:method?).and_return(false) - allow(probe).to receive(:line?).and_return(false) - allow(logger).to receive(:debug) - end - - it 'raises ArgumentError' do - expect do - instrumenter.hook_line(probe) - end.to raise_error(ArgumentError, /No block given/) - end - end - context 'non-executable line (comment)' do context 'without code tracking' do before do @@ -1071,13 +1075,13 @@ it 'installs trace point' do expect(TracePoint).to receive(:new).and_call_original - instrumenter.hook_line(probe) do |**opts| + hook_line(probe) do |**opts| fail 'should not get here' end end it 'does not invoke callback' do - instrumenter.hook_line(probe) do |**opts| + hook_line(probe) do |**opts| fail 'should not be invoked' end @@ -1108,7 +1112,7 @@ expect(TracePoint).not_to receive(:new) expect do - instrumenter.hook_line(probe) do |**opts| + hook_line(probe) do |**opts| fail 'should not get here' end end.to raise_error(Datadog::DI::Error::DITargetNotDefined) @@ -1133,7 +1137,7 @@ expect_any_instance_of(TracePoint).to receive(:enable).with(no_args).and_call_original - instrumenter.hook_line(probe) do |payload| + hook_line(probe) do |payload| observed_calls << payload end @@ -1158,7 +1162,7 @@ let(:payload) do expect_any_instance_of(TracePoint).to receive(:enable).with(no_args).and_call_original - instrumenter.hook_line(probe) do |payload| + hook_line(probe) do |payload| observed_calls << payload end @@ -1210,11 +1214,11 @@ it 'invokes callback twice' do expect(observed_calls).to be_empty - instrumenter.hook_line(probe) do |payload| + hook_line(probe) do |payload| observed_calls << payload end - instrumenter.hook_line(probe2) do |payload| + hook_line(probe2) do |payload| observed_calls << payload end @@ -1251,7 +1255,7 @@ expect_any_instance_of(TracePoint).to receive(:enable).with(target: target, target_line: 13).and_call_original - instrumenter.hook_line(probe) do |payload| + hook_line(probe) do |payload| observed_calls << payload end @@ -1274,7 +1278,7 @@ it 'invokes the instrumentation' do expect_any_instance_of(TracePoint).to receive(:enable).and_call_original - instrumenter.hook_line(probe) do |payload| + hook_line(probe) do |payload| observed_calls << payload end @@ -1291,7 +1295,7 @@ it 'invokes the instrumentation every time' do expect_any_instance_of(TracePoint).to receive(:enable).and_call_original - instrumenter.hook_line(probe) do |payload| + hook_line(probe) do |payload| observed_calls << payload end @@ -1314,7 +1318,7 @@ it 'raises DITargetNotInRegistry' do expect do - instrumenter.hook_line(probe) do |payload| + hook_line(probe) do |payload| end end.to raise_error(Datadog::DI::Error::DITargetNotInRegistry, /File matching probe path.*was loaded and is not in code tracker registry/) end @@ -1336,7 +1340,7 @@ end it 'invokes callback for every method invocation' do - instrumenter.hook_line(probe) do |payload| + hook_line(probe) do |payload| observed_calls << payload end @@ -1382,7 +1386,7 @@ end it 'invokes the callback only once' do - instrumenter.hook_line(probe) do |payload| + hook_line(probe) do |payload| observed_calls << payload end @@ -1415,7 +1419,7 @@ let(:payload) do expect_any_instance_of(TracePoint).to receive(:enable).and_call_original - instrumenter.hook_line(probe) do |payload| + hook_line(probe) do |payload| observed_calls << payload end @@ -1447,7 +1451,7 @@ end before do - instrumenter.hook_line(probe) do |payload| + hook_line(probe) do |payload| observed_calls << payload end end diff --git a/spec/datadog/di/integration/everything_from_remote_config_spec.rb b/spec/datadog/di/integration/everything_from_remote_config_spec.rb index ab5447e8ec3..52f16cbf341 100644 --- a/spec/datadog/di/integration/everything_from_remote_config_spec.rb +++ b/spec/datadog/di/integration/everything_from_remote_config_spec.rb @@ -562,7 +562,7 @@ def assert_received_and_errored context 'line probe with path containing extra prefix directories' do let(:probe_spec) do {id: '11', name: 'bar', type: 'LOG_PROBE', where: { - sourceFile: 'junk/prefix/instrumentation_integration_test_class.rb', lines: [22] + sourceFile: 'junk/prefix/instrumentation_integration_test_class.rb', lines: [42] }} end @@ -581,7 +581,7 @@ def assert_received_and_errored context 'line probe received targeting loaded code not in code tracker' do let(:probe_spec) do {id: '11', name: 'bar', type: 'LOG_PROBE', where: { - sourceFile: 'instrumentation_integration_test_class.rb', lines: [22] + sourceFile: 'instrumentation_integration_test_class.rb', lines: [42] }} end @@ -606,34 +606,281 @@ def assert_received_and_errored context 'when condition evaluation fails at runtime' do with_code_tracking - let(:propagate_all_exceptions) { false } + let(:propagate_all_exceptions) { true } let(:probe_spec) do { id: '11', name: 'bar', type: 'LOG_PROBE', where: { - sourceFile: 'hook_line_load.rb', lines: [34], + sourceFile: 'instrumentation_integration_test_class.rb', lines: [42], }, when: {json: {'contains' => [{'ref' => 'bar'}, 'baz']}, dsl: '(expression)'}, } end before do - load File.join(File.dirname(__FILE__), '../hook_line_load.rb') + load File.join(File.dirname(__FILE__), 'instrumentation_integration_test_class.rb') + end + + let(:evaluation_error_message) do + 'Datadog::DI::Error::ExpressionEvaluationError: Invalid arguments for contains: , baz' end - it 'executes target code still' do + let(:expected_snapshot_payload) do + { + path: '/debugger/v1/input', + # We do not have active span/trace in the test. + "dd.span_id": nil, + "dd.trace_id": nil, + "debugger.snapshot": { + captures: nil, + evaluationErrors: [ + {'expr' => '(expression)', 'message' => evaluation_error_message}, + ], + id: LOWERCASE_UUID_REGEXP, + language: 'ruby', + probe: { + id: '11', + location: { + file: String, + lines: [Integer], + }, + version: 0, + }, + stack: Array, + timestamp: Integer, + }, + ddsource: 'dd_debugger', + duration: Integer, + host: nil, + logger: { + method: nil, + name: 'instrumentation_integration_test_class.rb', + thread_id: nil, + thread_name: 'Thread.main', + version: 2, + }, + # No message since we stopped execution at condition evaluation. + message: nil, + service: 'rspec', + timestamp: Integer, + } + end + + it 'executes target code still and notifies about failed condition evaluation' do expect_lazy_log(logger, :debug, /received log probe at .+ via RC/) - # TODO report via evaluationErrors - expect_lazy_log(logger, :debug, /unhandled exception in line trace point: .*Invalid arguments for contains:/) do_rc(expect_hook: :hook_line) + assert_received_and_installed expect(probe_manager.installed_probes.length).to eq 1 probe = probe_manager.installed_probes.values.first expect(probe.condition).to be_a(Datadog::DI::EL::Expression) - rv = HookLineLoadTestClass.new.test_method_with_arg(5) - expect(rv).to be 5 + rv = InstrumentationIntegrationTestClass.new.test_method + expect(rv).to eq 42 + + component.probe_notifier_worker.flush + + # assertions + + expect(payloads.length).to eq 1 + + # No emitting payload because the probe hasn't emitted anything yet. + #emitting_payload = payloads.shift + #expect(emitting_payload).to match(expected_emitting_payload) + + snapshot_payload = payloads.shift + expect(order_hash_keys(snapshot_payload)).to match(deep_stringify_keys(order_hash_keys(expected_snapshot_payload))) + end + + context 'when second invocation successfully evaluates condition' do + let(:probe_spec) do + { + id: '11', name: 'bar', type: 'LOG_PROBE', + where: { + sourceFile: 'instrumentation_integration_test_class.rb', lines: [67], + }, + when: {json: {'contains' => [{'ref' => 'param'}, 'baz']}, dsl: '(expression)'}, + } + end + + let(:evaluation_error_message) do + 'Datadog::DI::Error::ExpressionEvaluationError: Invalid arguments for contains: false, baz' + end + + let(:expected_captures) { nil } + + let(:expected_second_snapshot_payload) do + { + path: '/debugger/v1/input', + # We do not have active span/trace in the test. + "dd.span_id": nil, + "dd.trace_id": nil, + "debugger.snapshot": { + captures: expected_captures, + evaluationErrors: [], + id: LOWERCASE_UUID_REGEXP, + language: 'ruby', + probe: { + id: '11', + location: { + file: File.join(File.dirname(__FILE__), 'instrumentation_integration_test_class.rb'), + lines: [67], + }, + version: 0, + }, + stack: Array, + timestamp: Integer, + }, + ddsource: 'dd_debugger', + duration: Integer, + host: nil, + logger: { + method: nil, + name: 'instrumentation_integration_test_class.rb', + thread_id: nil, + thread_name: 'Thread.main', + version: 2, + }, + message: nil, + service: 'rspec', + timestamp: Integer, + } + end + + it 'notifies emitting on second invocation' do + expect_lazy_log(logger, :debug, /received log probe at .+ via RC/) + do_rc(expect_hook: :hook_line) + assert_received_and_installed + + expect(probe_manager.installed_probes.length).to eq 1 + probe = probe_manager.installed_probes.values.first + expect(probe.condition).to be_a(Datadog::DI::EL::Expression) + + rv = InstrumentationIntegrationTestClass.new.test_method_with_conditional + expect(rv).to eq 1 + + component.probe_notifier_worker.flush + + # assertions + + expect(payloads.length).to eq 1 + + # No emitting payload because the probe hasn't emitted anything yet. + #emitting_payload = payloads.shift + #expect(emitting_payload).to match(expected_emitting_payload) + + snapshot_payload = payloads.shift + expect(order_hash_keys(snapshot_payload)).to match(deep_stringify_keys(order_hash_keys(expected_snapshot_payload))) + + # Second call with a different type of value passed in as parameter. + # Condition evaluation does not raise an exception but + # the condition is not met. + rv = InstrumentationIntegrationTestClass.new.test_method_with_conditional('hello foo') + expect(rv).to eq 2 + + component.probe_notifier_worker.flush + + # assertions + + # No new payloads since condition wasn't met and probe + # was not executed. + expect(payloads.length).to eq 0 + + # Condition is met for this invocation. + rv = InstrumentationIntegrationTestClass.new.test_method_with_conditional('hello baz') + expect(rv).to eq 2 + + component.probe_notifier_worker.flush + + # assertions + + expect(payloads.length).to eq 2 + + emitting_payload = payloads.shift + expect(emitting_payload).to match(expected_emitting_payload) + + snapshot_payload = payloads.shift + expect(order_hash_keys(snapshot_payload)).to match(deep_stringify_keys(order_hash_keys(expected_second_snapshot_payload))) + end + + context 'when code is invoked several times' do + let(:probe_spec) do + { + id: '11', name: 'bar', type: 'LOG_PROBE', + where: { + sourceFile: 'instrumentation_integration_test_class.rb', lines: [67], + }, + when: {json: {'contains' => [{'ref' => 'param'}, 'baz']}, dsl: '(expression)'}, + # Enable snapshot capture to get the lower rate limit (1/second) + captureSnapshot: true, + } + end + + let(:expected_captures) { Hash } + + it 'respects rate limits' do + expect_lazy_log(logger, :debug, /received log probe at .+ via RC/) + do_rc(expect_hook: :hook_line) + assert_received_and_installed + + expect(probe_manager.installed_probes.length).to eq 1 + probe = probe_manager.installed_probes.values.first + expect(probe.condition).to be_a(Datadog::DI::EL::Expression) + + rv = InstrumentationIntegrationTestClass.new.test_method_with_conditional + expect(rv).to eq 1 + + component.probe_notifier_worker.flush + + # assertions + + expect(payloads.length).to eq 1 + + # No emitting payload because the probe hasn't emitted anything yet. + #emitting_payload = payloads.shift + #expect(emitting_payload).to match(expected_emitting_payload) + + snapshot_payload = payloads.shift + expect(order_hash_keys(snapshot_payload)).to match(deep_stringify_keys(order_hash_keys(expected_snapshot_payload))) + + # Identical call - will not cause anything to be emitted + # due to rate limit on evaluation error reporting. + + rv = InstrumentationIntegrationTestClass.new.test_method_with_conditional + expect(rv).to eq 1 + + component.probe_notifier_worker.flush + + expect(payloads.length).to eq 0 + + # Condition is met for this invocation. + rv = InstrumentationIntegrationTestClass.new.test_method_with_conditional('hello baz') + expect(rv).to eq 2 + + component.probe_notifier_worker.flush + + # assertions + + expect(payloads.length).to eq 2 + + emitting_payload = payloads.shift + expect(emitting_payload).to match(expected_emitting_payload) + + snapshot_payload = payloads.shift + expect(order_hash_keys(snapshot_payload)).to match(deep_stringify_keys(order_hash_keys(expected_second_snapshot_payload))) + + # Call again - no payloads emitted because of rate limit. + rv = InstrumentationIntegrationTestClass.new.test_method_with_conditional('hello baz') + expect(rv).to eq 2 + + component.probe_notifier_worker.flush + + # assertions + + expect(payloads.length).to eq 0 + end + end end end end diff --git a/spec/datadog/di/integration/instrumentation_integration_test_class.rb b/spec/datadog/di/integration/instrumentation_integration_test_class.rb index 01d45a7d419..1ccce599abe 100644 --- a/spec/datadog/di/integration/instrumentation_integration_test_class.rb +++ b/spec/datadog/di/integration/instrumentation_integration_test_class.rb @@ -1,10 +1,30 @@ # rubocop:disable all -class InstrumentationIntegrationTestClass - # padding +begin + Object.send(:remove_const, :InstrumentationIntegrationTestClass) +rescue NameError +end + +# padding +# padding +# padding +# padding +# padding +# padding +# padding +# padding +# padding +# padding +# padding +# padding +# padding +# padding +# padding +# padding +class InstrumentationIntegrationTestClass def method_with_no_locals - 42 # line 7 + 42 # line 27 end # padding @@ -17,9 +37,9 @@ def test_method # to be invoked multiple times in CircleCI on Ruby 3.0-3.2 and 3.4 #if true || password || redacted if true - a * 2 # line 20 + a * 2 # line 40 end - end # line 22 + end # line 42 # Constructor is here to keep existing line number references intact def initialize @@ -30,7 +50,7 @@ def test_method_with_block array = [1] array.each do |value| value - end # line 33 + end # line 53 end # padding @@ -38,17 +58,17 @@ def test_method_with_block # padding # padding - def test_method_with_conditional - if false + def test_method_with_conditional(param = false) + if param == false a = 1 - else # line 44 + else # line 64 a = 2 - end # line 46 + end # line 66 a end -end # line 50 +end # line 70 # padding -# Comment - line 54 +# Comment - line 74 diff --git a/spec/datadog/di/integration/instrumentation_spec.rb b/spec/datadog/di/integration/instrumentation_spec.rb index 45937482a96..667e280e10a 100644 --- a/spec/datadog/di/integration/instrumentation_spec.rb +++ b/spec/datadog/di/integration/instrumentation_spec.rb @@ -616,7 +616,7 @@ def run_test context 'simple log probe' do let(:probe) do Datadog::DI::Probe.new(id: "1234", type: :log, - file: 'instrumentation_integration_test_class.rb', line_no: 20, + file: 'instrumentation_integration_test_class.rb', line_no: 40, capture_snapshot: false,) end @@ -680,7 +680,7 @@ def run_test context 'target line is the end line of a method' do let(:probe) do Datadog::DI::Probe.new(id: "1234", type: :log, - file: 'instrumentation_integration_test_class.rb', line_no: 22, + file: 'instrumentation_integration_test_class.rb', line_no: 42, capture_snapshot: false,) end @@ -690,7 +690,7 @@ def run_test context 'target line is the end line of a block' do let(:probe) do Datadog::DI::Probe.new(id: "1234", type: :log, - file: 'instrumentation_integration_test_class.rb', line_no: 33, + file: 'instrumentation_integration_test_class.rb', line_no: 53, capture_snapshot: false,) end @@ -760,12 +760,12 @@ def run_test context 'target line is else of a conditional' do let(:probe) do Datadog::DI::Probe.new(id: "1234", type: :log, - file: 'instrumentation_integration_test_class.rb', line_no: 44, + file: 'instrumentation_integration_test_class.rb', line_no: 64, capture_snapshot: false,) end let(:call_target) do - expect(InstrumentationIntegrationTestClass.new.test_method_with_conditional).to eq(2) + expect(InstrumentationIntegrationTestClass.new.test_method_with_conditional).to eq(1) end include_examples 'installs but does not invoke probe' @@ -774,12 +774,12 @@ def run_test context 'target line is end of a conditional' do let(:probe) do Datadog::DI::Probe.new(id: "1234", type: :log, - file: 'instrumentation_integration_test_class.rb', line_no: 46, + file: 'instrumentation_integration_test_class.rb', line_no: 66, capture_snapshot: false,) end let(:call_target) do - expect(InstrumentationIntegrationTestClass.new.test_method_with_conditional).to eq(2) + expect(InstrumentationIntegrationTestClass.new.test_method_with_conditional).to eq(1) end include_examples 'installs but does not invoke probe' @@ -788,7 +788,7 @@ def run_test context 'target line contains a comment (no executable code)' do let(:probe) do Datadog::DI::Probe.new(id: "1234", type: :log, - file: 'instrumentation_integration_test_class.rb', line_no: 50, + file: 'instrumentation_integration_test_class.rb', line_no: 70, capture_snapshot: false,) end @@ -802,7 +802,7 @@ def run_test context 'target line is in a loaded file that is not in code tracker' do let(:probe) do Datadog::DI::Probe.new(id: "1234", type: :log, - file: 'instrumentation_integration_test_class.rb', line_no: 33, + file: 'instrumentation_integration_test_class.rb', line_no: 53, capture_snapshot: false,) end @@ -836,12 +836,12 @@ def run_test context 'enriched probe' do let(:probe) do Datadog::DI::Probe.new(id: "1234", type: :log, - file: 'instrumentation_integration_test_class.rb', line_no: 20, + file: 'instrumentation_integration_test_class.rb', line_no: 40, capture_snapshot: true,) end let(:expected_captures) do - {lines: {20 => { + {lines: {40 => { locals: { a: {type: 'Integer', value: '21'}, password: {type: 'String', notCapturedReason: 'redactedIdent'}, @@ -900,12 +900,12 @@ def run_test context 'when there are instance variables but no local variables' do let(:probe) do Datadog::DI::Probe.new(id: "1234", type: :log, - file: 'instrumentation_integration_test_class.rb', line_no: 7, + file: 'instrumentation_integration_test_class.rb', line_no: 27, capture_snapshot: true,) end let(:expected_captures) do - {lines: {7 => { + {lines: {27 => { # Reports instance variables but no locals locals: {}, arguments: { @@ -1036,7 +1036,7 @@ def run_test let(:probe) do Datadog::DI::Probe.new(id: "1234", type: :log, - file: 'instrumentation_integration_test_class.rb', line_no: 20, + file: 'instrumentation_integration_test_class.rb', line_no: 40, capture_snapshot: false,) end diff --git a/spec/datadog/di/probe_notification_builder_spec.rb b/spec/datadog/di/probe_notification_builder_spec.rb index dcd023c8307..86e673461a3 100644 --- a/spec/datadog/di/probe_notification_builder_spec.rb +++ b/spec/datadog/di/probe_notification_builder_spec.rb @@ -201,7 +201,7 @@ service: 'test service', timestamp: Integer, logger: { - method: 'no_method', + method: nil, name: 'X', thread_id: nil, thread_name: 'Thread.main', @@ -249,7 +249,7 @@ service: 'test service', timestamp: Integer, logger: { - method: 'no_method', + method: nil, name: 'X', thread_id: nil, thread_name: 'Thread.main', @@ -322,7 +322,7 @@ service: 'test service', timestamp: Integer, logger: { - method: 'no_method', + method: nil, name: 'X', thread_id: nil, thread_name: 'Thread.main',