Merge pull request #4035 from DataDog/appsec-55378-restructure-contex…

…t-logging-and-telemetry [APPSEC-55378] Rework Processor::Context logging and telemetry
DataDog · Oct 28, 2024 · 7302d7b · 7302d7b
2 parents d77045d + dc1b88f
commit 7302d7b
Show file tree

Hide file tree

Showing 10 changed files with 92 additions and 140 deletions.
diff --git a/lib/datadog/appsec/contrib/graphql/reactive/multiplex.rb b/lib/datadog/appsec/contrib/graphql/reactive/multiplex.rb
@@ -32,23 +32,10 @@ def self.subscribe(op, waf_context)
                 waf_timeout = Datadog.configuration.appsec.waf_timeout
                 result = waf_context.run(waf_args, waf_timeout)
 
-                Datadog.logger.debug { "WAF TIMEOUT: #{result.inspect}" } if result.timeout
-
-                case result.status
-                when :match
-                  Datadog.logger.debug { "WAF: #{result.inspect}" }
-
-                  yield result
-                  throw(:block, true) unless result.actions.empty?
-                when :ok
-                  Datadog.logger.debug { "WAF OK: #{result.inspect}" }
-                when :invalid_call
-                  Datadog.logger.debug { "WAF CALL ERROR: #{result.inspect}" }
-                when :invalid_rule, :invalid_flow, :no_rule
-                  Datadog.logger.debug { "WAF RULE ERROR: #{result.inspect}" }
-                else
-                  Datadog.logger.debug { "WAF UNKNOWN: #{result.status.inspect} #{result.inspect}" }
-                end
+                next if result.status != :match
+
+                yield result
+                throw(:block, true) unless result.actions.empty?
               end
             end
           end

diff --git a/lib/datadog/appsec/contrib/rack/reactive/request.rb b/lib/datadog/appsec/contrib/rack/reactive/request.rb
@@ -33,6 +33,7 @@ def self.publish(op, gateway_request)
             def self.subscribe(op, waf_context)
               op.subscribe(*ADDRESSES) do |*values|
                 Datadog.logger.debug { "reacted to #{ADDRESSES.inspect}: #{values.inspect}" }
+
                 headers = values[0]
                 headers_no_cookies = headers.dup.tap { |h| h.delete('cookie') }
                 uri_raw = values[1]
@@ -54,23 +55,10 @@ def self.subscribe(op, waf_context)
                 waf_timeout = Datadog.configuration.appsec.waf_timeout
                 result = waf_context.run(waf_args, waf_timeout)
 
-                Datadog.logger.debug { "WAF TIMEOUT: #{result.inspect}" } if result.timeout
-
-                case result.status
-                when :match
-                  Datadog.logger.debug { "WAF: #{result.inspect}" }
+                next if result.status != :match
 
-                  yield result
-                  throw(:block, true) unless result.actions.empty?
-                when :ok
-                  Datadog.logger.debug { "WAF OK: #{result.inspect}" }
-                when :invalid_call
-                  Datadog.logger.debug { "WAF CALL ERROR: #{result.inspect}" }
-                when :invalid_rule, :invalid_flow, :no_rule
-                  Datadog.logger.debug { "WAF RULE ERROR: #{result.inspect}" }
-                else
-                  Datadog.logger.debug { "WAF UNKNOWN: #{result.status.inspect} #{result.inspect}" }
-                end
+                yield result
+                throw(:block, true) unless result.actions.empty?
               end
             end
           end

diff --git a/lib/datadog/appsec/contrib/rack/reactive/request_body.rb b/lib/datadog/appsec/contrib/rack/reactive/request_body.rb
@@ -33,23 +33,10 @@ def self.subscribe(op, waf_context)
                 waf_timeout = Datadog.configuration.appsec.waf_timeout
                 result = waf_context.run(waf_args, waf_timeout)
 
-                Datadog.logger.debug { "WAF TIMEOUT: #{result.inspect}" } if result.timeout
-
-                case result.status
-                when :match
-                  Datadog.logger.debug { "WAF: #{result.inspect}" }
-
-                  yield result
-                  throw(:block, true) unless result.actions.empty?
-                when :ok
-                  Datadog.logger.debug { "WAF OK: #{result.inspect}" }
-                when :invalid_call
-                  Datadog.logger.debug { "WAF CALL ERROR: #{result.inspect}" }
-                when :invalid_rule, :invalid_flow, :no_rule
-                  Datadog.logger.debug { "WAF RULE ERROR: #{result.inspect}" }
-                else
-                  Datadog.logger.debug { "WAF UNKNOWN: #{result.status.inspect} #{result.inspect}" }
-                end
+                next if result.status != :match
+
+                yield result
+                throw(:block, true) unless result.actions.empty?
               end
             end
           end

diff --git a/lib/datadog/appsec/contrib/rack/reactive/response.rb b/lib/datadog/appsec/contrib/rack/reactive/response.rb
@@ -39,23 +39,10 @@ def self.subscribe(op, waf_context)
                 waf_timeout = Datadog.configuration.appsec.waf_timeout
                 result = waf_context.run(waf_args, waf_timeout)
 
-                Datadog.logger.debug { "WAF TIMEOUT: #{result.inspect}" } if result.timeout
+                next if result.status != :match
 
-                case result.status
-                when :match
-                  Datadog.logger.debug { "WAF: #{result.inspect}" }
-
-                  yield result
-                  throw(:block, true) unless result.actions.empty?
-                when :ok
-                  Datadog.logger.debug { "WAF OK: #{result.inspect}" }
-                when :invalid_call
-                  Datadog.logger.debug { "WAF CALL ERROR: #{result.inspect}" }
-                when :invalid_rule, :invalid_flow, :no_rule
-                  Datadog.logger.debug { "WAF RULE ERROR: #{result.inspect}" }
-                else
-                  Datadog.logger.debug { "WAF UNKNOWN: #{result.status.inspect} #{result.inspect}" }
-                end
+                yield result
+                throw(:block, true) unless result.actions.empty?
               end
             end
           end

diff --git a/lib/datadog/appsec/contrib/rails/reactive/action.rb b/lib/datadog/appsec/contrib/rails/reactive/action.rb
@@ -39,23 +39,10 @@ def self.subscribe(op, waf_context)
                 waf_timeout = Datadog.configuration.appsec.waf_timeout
                 result = waf_context.run(waf_args, waf_timeout)
 
-                Datadog.logger.debug { "WAF TIMEOUT: #{result.inspect}" } if result.timeout
+                next if result.status != :match
 
-                case result.status
-                when :match
-                  Datadog.logger.debug { "WAF: #{result.inspect}" }
-
-                  yield result
-                  throw(:block, true) unless result.actions.empty?
-                when :ok
-                  Datadog.logger.debug { "WAF OK: #{result.inspect}" }
-                when :invalid_call
-                  Datadog.logger.debug { "WAF CALL ERROR: #{result.inspect}" }
-                when :invalid_rule, :invalid_flow, :no_rule
-                  Datadog.logger.debug { "WAF RULE ERROR: #{result.inspect}" }
-                else
-                  Datadog.logger.debug { "WAF UNKNOWN: #{result.status.inspect} #{result.inspect}" }
-                end
+                yield result
+                throw(:block, true) unless result.actions.empty?
               end
             end
           end

diff --git a/lib/datadog/appsec/contrib/sinatra/reactive/routed.rb b/lib/datadog/appsec/contrib/sinatra/reactive/routed.rb
@@ -34,23 +34,10 @@ def self.subscribe(op, waf_context)
                 waf_timeout = Datadog.configuration.appsec.waf_timeout
                 result = waf_context.run(waf_args, waf_timeout)
 
-                Datadog.logger.debug { "WAF TIMEOUT: #{result.inspect}" } if result.timeout
-
-                case result.status
-                when :match
-                  Datadog.logger.debug { "WAF: #{result.inspect}" }
-
-                  yield result
-                  throw(:block, true) unless result.actions.empty?
-                when :ok
-                  Datadog.logger.debug { "WAF OK: #{result.inspect}" }
-                when :invalid_call
-                  Datadog.logger.debug { "WAF CALL ERROR: #{result.inspect}" }
-                when :invalid_rule, :invalid_flow, :no_rule
-                  Datadog.logger.debug { "WAF RULE ERROR: #{result.inspect}" }
-                else
-                  Datadog.logger.debug { "WAF UNKNOWN: #{result.status.inspect} #{result.inspect}" }
-                end
+                next if result.status != :match
+
+                yield result
+                throw(:block, true) unless result.actions.empty?
               end
             end
           end

diff --git a/lib/datadog/appsec/monitor/reactive/set_user.rb b/lib/datadog/appsec/monitor/reactive/set_user.rb
@@ -32,23 +32,10 @@ def self.subscribe(op, waf_context)
               waf_timeout = Datadog.configuration.appsec.waf_timeout
               result = waf_context.run(waf_args, waf_timeout)
 
-              Datadog.logger.debug { "WAF TIMEOUT: #{result.inspect}" } if result.timeout
-
-              case result.status
-              when :match
-                Datadog.logger.debug { "WAF: #{result.inspect}" }
-
-                yield result
-                throw(:block, true) unless result.actions.empty?
-              when :ok
-                Datadog.logger.debug { "WAF OK: #{result.inspect}" }
-              when :invalid_call
-                Datadog.logger.debug { "WAF CALL ERROR: #{result.inspect}" }
-              when :invalid_rule, :invalid_flow, :no_rule
-                Datadog.logger.debug { "WAF RULE ERROR: #{result.inspect}" }
-              else
-                Datadog.logger.debug { "WAF UNKNOWN: #{result.status.inspect} #{result.inspect}" }
-              end
+              next if result.status != :match
+
+              yield result
+              throw(:block, true) unless result.actions.empty?
             end
           end
         end

diff --git a/lib/datadog/appsec/processor/context.rb b/lib/datadog/appsec/processor/context.rb
@@ -1,21 +1,27 @@
 # frozen_string_literal: true
 
+require 'libddwaf'
+
 module Datadog
   module AppSec
     class Processor
       # Context manages a sequence of runs
       class Context
+        LIBDDWAF_SUCCESSFUL_EXECUTION_CODES = [:ok, :match].freeze
+
         attr_reader :time_ns, :time_ext_ns, :timeouts, :events
 
         def initialize(handle, telemetry:)
-          @context = Datadog::AppSec::WAF::Context.new(handle)
+          @context = WAF::Context.new(handle)
           @telemetry = telemetry
 
           @time_ns = 0.0
           @time_ext_ns = 0.0
           @timeouts = 0
           @events = []
           @run_mutex = Mutex.new
+
+          @libddwaf_tag = "libddwaf:#{WAF::VERSION::STRING}"
         end
 
         def run(input, timeout = WAF::LibDDWAF::DDWAF_RUN_TIMEOUT)
@@ -24,24 +30,22 @@ def run(input, timeout = WAF::LibDDWAF::DDWAF_RUN_TIMEOUT)
           start_ns = Core::Utils::Time.get_time(:nanosecond)
 
           input.reject! do |_, v|
-            case v
-            when TrueClass, FalseClass
-              false
-            else
-              v.nil? ? true : v.empty?
-            end
+            next false if v.is_a?(TrueClass) || v.is_a?(FalseClass)
+
+            v.nil? ? true : v.empty?
           end
 
-          _code, res = @context.run(input, timeout)
+          _code, result = @context.run(input, timeout)
 
           stop_ns = Core::Utils::Time.get_time(:nanosecond)
 
           # these updates are not thread safe and should be protected
-          @time_ns += res.total_runtime
+          @time_ns += result.total_runtime
           @time_ext_ns += (stop_ns - start_ns)
-          @timeouts += 1 if res.timeout
+          @timeouts += 1 if result.timeout
 
-          res
+          report_execution(result)
+          result
         ensure
           @run_mutex.unlock
         end
@@ -55,9 +59,10 @@ def extract_schema
             }
           }
 
-          _code, res = @context.run(input, WAF::LibDDWAF::DDWAF_RUN_TIMEOUT)
+          _code, result = @context.run(input, WAF::LibDDWAF::DDWAF_RUN_TIMEOUT)
 
-          res
+          report_execution(result)
+          result
         end
 
         def finalize
@@ -66,6 +71,19 @@ def finalize
 
         private
 
+        def report_execution(result)
+          Datadog.logger.debug { "#{@libddwaf_tag} execution timed out: #{result.inspect}" } if result.timeout
+
+          if LIBDDWAF_SUCCESSFUL_EXECUTION_CODES.include?(result.status)
+            Datadog.logger.debug { "#{@libddwaf_tag} execution result: #{result.inspect}" }
+          else
+            message = "#{@libddwaf_tag} execution error: #{result.status.inspect}"
+
+            Datadog.logger.debug { message }
+            @telemetry.error(message)
+          end
+        end
+
         def extract_schema?
           Datadog.configuration.appsec.api_security.enabled &&
             Datadog.configuration.appsec.api_security.sample_rate.sample?

diff --git a/sig/datadog/appsec/processor/context.rbs b/sig/datadog/appsec/processor/context.rbs
@@ -16,6 +16,10 @@ module Datadog
 
         @run_mutex: ::Thread::Mutex
 
+        @libddwaf_tag: ::String
+
+        LIBDDWAF_SUCCESSFUL_EXECUTION_CODES: ::Array[::Symbol]
+
         attr_reader time_ns: ::Float
 
         attr_reader time_ext_ns: ::Float
@@ -34,6 +38,8 @@ module Datadog
 
         private
 
+        def report_execution: (WAF::Result result) -> void
+
         def extract_schema?: () -> bool
       end
     end

diff --git a/spec/datadog/appsec/processor/context_spec.rb b/spec/datadog/appsec/processor/context_spec.rb
@@ -78,13 +78,8 @@
       results.reject { |r| r.status == :ok }
     end
 
-    let(:events) do
-      matches.map(&:events).flatten
-    end
-
-    let(:actions) do
-      matches.map(&:actions)
-    end
+    let(:events) { matches.flat_map(&:events) }
+    let(:actions) { matches.map(&:actions) }
 
     context 'clear key with empty values' do
       it 'removes nil values' do
@@ -171,6 +166,7 @@
     context 'one attack' do
       let(:input) { input_scanner }
 
+      it { expect(telemetry).not_to receive(:error) }
       it { expect(matches).to have_attributes(count: 1) }
       it { expect(events).to have_attributes(count: 1) }
       it { expect(actions).to eq [[]] }
@@ -237,6 +233,28 @@
       it { expect(events).to have_attributes(count: 1) }
       it { expect(actions).to eq [['block']] }
     end
+
+    context 'run failed with libddwaf error result' do
+      before do
+        allow(context.instance_variable_get(:@context)).to receive(:run).with(input, timeout)
+          .and_return([result.status, result])
+      end
+
+      let(:result) do
+        instance_double(
+          Datadog::AppSec::WAF::Result,
+          status: :err_invalid_object,
+          total_runtime: 0.01,
+          timeout: false
+        )
+      end
+
+      it 'sends telemetry error' do
+        expect(telemetry).to receive(:error).with(/libddwaf:[\d.]+ execution error: :err_invalid_object/)
+
+        context.run(input, timeout)
+      end
+    end
   end
 
   describe '#extract_schema' do
@@ -257,15 +275,14 @@
           }
         }
 
-        dummy_code = 1
-        dummy_result = 2
+        result = instance_double(Datadog::AppSec::WAF::Result, status: :ok, timeout: false)
 
         expect(context.instance_variable_get(:@context)).to receive(:run).with(
           input,
           Datadog::AppSec::WAF::LibDDWAF::DDWAF_RUN_TIMEOUT
-        ).and_return([dummy_code, dummy_result])
+        ).and_return([result.status, result])
 
-        expect(context.extract_schema).to eq dummy_result
+        expect(context.extract_schema).to eq result
       end
 
       it 'returns schema extraction information' do
@@ -274,6 +291,7 @@
 
         results = context.extract_schema
         derivatives = results.derivatives
+
         expect(derivatives).to_not be_empty
         expect(derivatives['_dd.appsec.s.req.query']).to eq([{ 'vin' => [8, { 'category' => 'pii', 'type' => 'vin' }] }])
       end