# typed: false # Copyright (c) 2015 Sqreen. All Rights Reserved. # Please refer to our terms for more information: https://www.sqreen.com/terms.html require 'sqreen/weave/legacy' require 'sqreen/weave/budget' require 'sqreen/graft/hook' require 'sqreen/graft/hook_point' require 'sqreen/call_countable' require 'sqreen/rules' require 'sqreen/rules/record_request_context' require 'sqreen/sqreen_signed_verifier' class Sqreen::Weave::Legacy::Instrumentation attr_accessor :metrics_engine def initialize(metrics_engine, opts = {}) Sqreen::Weave.logger.debug { "#{self.class.name}#initialize #{metrics_engine}" } @hooks = [] self.metrics_engine = metrics_engine ### bail out if no metric engine return if metrics_engine.nil? ### init metric to count calls to sqreen metrics_engine.create_metric( 'name' => 'sqreen_call_counts', 'period' => 60, 'kind' => 'Sum', ) ### init metric to count request whitelist matches (ip or path whitelist) metrics_engine.create_metric( 'name' => 'whitelisted', 'period' => 60, 'kind' => 'Sum', ) ### init metric to count over budget hits metrics_engine.create_metric( 'name' => 'request_overtime', 'period' => 60, 'kind' => 'Sum', ) # PerformanceNotifications::Binning metrics_engine.create_metric( 'name' => 'req', 'period' => opts[:period] || 60, 'kind' => 'Binning', 'options' => opts[:perf_metric] || { 'base' => 2.0, 'factor' => 0.1 }, ) metrics_engine.create_metric( 'name' => 'sq', 'period' => opts[:period] || 60, 'kind' => 'Binning', 'options' => opts[:perf_metric] || { 'base' => 2.0, 'factor' => 0.1 }, ) metrics_engine.create_metric( 'name' => 'pct', 'period' => opts[:period] || 60, 'kind' => 'Binning', 'options' => opts[:perf_metric_percent] || { 'base' => 1.3, 'factor' => 1.0 }, ) metrics_engine.create_metric( 'name' => 'req.sq.hook.overhead', 'period' => 60, 'kind' => 'Binning', 'options' => { 'base' => 2.0, 'factor' => 0.1 }, ) metrics_engine.create_metric( 'name' => 'sq.hook.overhead', 'period' => 60, 'kind' => 'Binning', 'options' => { 'base' => 2.0, 'factor' => 0.1 }, ) metrics_engine.create_metric( 'name' => 'sq.shrinkwrap', 'period' => 60, 'kind' => 'Binning', 'options' => { 'base' => 2.0, 'factor' => 0.1 }, ) Sqreen.thread_cpu_time? && metrics_engine.create_metric( 'name' => 'sq_thread_cpu_pct', 'period' => opts[:period] || 60, 'kind' => 'Binning', 'options' => opts[:perf_metric_percent] || { 'base' => 1.3, 'factor' => 1.0 }, ) end # needed by Sqreen::Runner#initialize def instrument!(rules, framework) Sqreen::Weave.logger.debug { "#{rules.count} rules, #{framework}" } strategy = Sqreen.config_get(:weave_strategy) if strategy == :prepend && !Module.respond_to?(:prepend) Sqreen::Weave.logger.warn { "strategy: #{strategy.inspect} unavailable, falling back to :chain" } strategy = :chain elsif strategy == :chain && Gem::Specification.select { |s| s.name == 'scout_apm' && Gem::Requirement.new('>= 2.5.2').satisfied_by?(Gem::Version.new(s.version)) }.any? Sqreen::Weave.logger.warn { "strategy: #{strategy.inspect} unavailable with scout_apm >= 2.5.2, switching to :prepend" } strategy = :prepend end Sqreen::Weave.logger.debug { "strategy: #{strategy.inspect}" } ### set up rule signature verifier verifier = nil if Sqreen.features['rules_signature'] && Sqreen.config_get(:rules_verify_signature) == true && !defined?(::JRUBY_VERSION) verifier = Sqreen::SqreenSignedVerifier.new Sqreen::Weave.logger.debug('Rules signature enabled') else Sqreen::Weave.logger.debug('Rules signature disabled') end ### force clean instrumentation callback list @hooks = [] ### for each rule description rules.each do |rule| Sqreen::Weave.logger.debug { "Processing rule: #{rule['name']}" } ### transform into format for adding callback rule_callback = Sqreen::Rules.cb_from_rule(rule, self, metrics_engine, verifier) next unless rule_callback ### attach framework to callback rule_callback.framework = framework ## create metric Sqreen::Weave.logger.debug { "Adding rule metric: #{rule_callback}" } [:pre, :post, :failing].each do |whence| next unless rule_callback.send(:"#{whence}?") metric_name = "sq.#{rule['name']}.#{whence}" metrics_engine.create_metric( 'name' => metric_name, 'period' => 60, 'kind' => 'Binning', 'options' => { 'base' => 2.0, 'factor' => 0.1 }, ) metric_name = "req.sq.#{rule['name']}.#{whence}" metrics_engine.create_metric( 'name' => metric_name, 'period' => 60, 'kind' => 'Binning', 'options' => { 'base' => 2.0, 'factor' => 0.1 }, ) end ### install callback, observing priority Sqreen::Weave.logger.debug { "Adding rule callback: #{rule_callback}" } @hooks << add_callback("weave,rule=#{rule['name']}", rule_callback, strategy) end ### for each hardcoded callback hardcoded_callbacks(framework).each do |hard_callback| Sqreen::Weave.logger.debug { "Adding hardcoded callback: #{hard_callback}" } ### install hardcoded callbacks, observing priority @hooks << add_callback('weave,hardcoded', hard_callback, strategy) end metrics_engine = self.metrics_engine request_hook = Sqreen::Graft::Hook['Sqreen::ShrinkWrap#call', strategy] @hooks << request_hook request_hook.add do before('wave,meta,request', rank: -100000, mandatory: true) do |_call| next unless Sqreen.instrumentation_ready # shrinkwrap_timer = Sqreen::Graft::Timer.new('weave,shrinkwrap') # shrinkwrap_timer.start request_timer = Sqreen::Graft::Timer.new("request") request_timer.start sqreen_timer = Sqreen::Graft::Timer.new("sqreen") budget = Sqreen::Weave::Budget.current request_budget_threshold = budget.threshold if budget request_budget_ratio = budget.ratio if budget request_budget_is_dynamic = !request_budget_ratio.nil? request_budget = !request_budget_threshold.nil? timed_level = (Sqreen.features['perf_level'] || 1).to_i Sqreen::Weave.logger.debug { "request budget: #{budget.to_h} timed.level: #{timed_level}" } if Sqreen::Weave.logger.debug? Thread.current[:sqreen_http_request] = { request_timer: request_timer, sqreen_timer: sqreen_timer, time_budget_expended: false, time_budget_threshold: request_budget_threshold, time_budget_dynamic: request_budget_is_dynamic, time_budget_ratio: request_budget_ratio, time_budget: request_budget, timed_callbacks: [], timed_hooks: [], timed_level: timed_level, skipped_callbacks: [], # timed_shrinkwrap: shrinkwrap_timer, } # shrinkwrap_timer.stop end ensured('weave,meta,request', rank: 100000, mandatory: true) do |_call| request = Thread.current[:sqreen_http_request] next if request.nil? # shrinkwrap_timer = request[:timed_shrinkwrap] # shrinkwrap_timer.start Thread.current[:sqreen_http_request] = nil request_timer = request[:request_timer] now = request_timer.stop if request[:timed_level] >= 1 request[:timed_callbacks].each do |timer| duration = timer.duration timer.tag =~ /weave,rule=(.*)$/ && rule = $1 next unless rule whence = case timer.tag when /@before/ then 'pre' when /@after/ then 'post' when /@raised/ then 'failing' end next unless whence metric_name = "sq.#{rule}.#{whence}" metrics_engine.update(metric_name, now, nil, duration * 1000) # Sqreen.observations_queue.push([metric_name, nil, duration * 1000, utc_now]) end request[:timed_hooks].each do |timer| duration = timer.duration metrics_engine.update('sq.hook.overhead', now, nil, duration * 1000) # Sqreen.observations_queue.push(['sq.hook.overhead', nil, duration * 1000, utc_now]) end end sqreen_timer = request[:sqreen_timer] total = sqreen_timer.duration Sqreen::Weave.logger.debug { "request sqreen_timer.total: #{'%.03fus' % (total * 1_000_000)}" } if Sqreen::Weave.logger.debug? total = request_timer.duration Sqreen::Weave.logger.debug { "request request_timer.total: #{'%.03fus' % (total * 1_000_000)}" } if Sqreen::Weave.logger.debug? if request[:timed_level] >= 2 skipped = request[:skipped_callbacks].map(&:name) Sqreen::Weave.logger.debug { "request callback.skipped.count: #{skipped.count}" } if Sqreen::Weave.logger.debug? timings = request[:timed_callbacks].map(&:to_s) total = request[:timed_callbacks].sum(&:duration) Sqreen::Weave.logger.debug { "request callback.total: #{'%.03fus' % (total * 1_000_000)} callback.count: #{timings.count}" } if Sqreen::Weave.logger.debug? timings = request[:timed_hooks].map(&:to_s) total = request[:timed_hooks].sum(&:duration) Sqreen::Weave.logger.debug { "request hook.total: #{'%.03fus' % (total * 1_000_000)} hook.count: #{timings.count}" } if Sqreen::Weave.logger.debug? end skipped = request[:skipped_callbacks].map(&:name) skipped_rule_name = skipped.first && skipped.first =~ /weave,rule=(.*)$/ && $1 metrics_engine.update('request_overtime', now, skipped_rule_name, 1) if skipped_rule_name # Sqreen.observations_queue.push(['request_overtime', skipped_rule_name, 1, utc_now]) if skipped_rule_name sqreen_request_duration = sqreen_timer.duration metrics_engine.update('sq', now, nil, sqreen_request_duration * 1000) # Sqreen.observations_queue.push(['sq', nil, sqreen_request_duration * 1000, utc_now]) request_duration = request_timer.duration metrics_engine.update('req', now, nil, request_duration * 1000) # Sqreen.observations_queue.push(['req', nil, request_duration * 1000, utc_now]) sqreen_request_ratio = (sqreen_request_duration * 100.0) / (request_duration - sqreen_request_duration) metrics_engine.update('pct', now, nil, sqreen_request_ratio) # Sqreen.observations_queue.push(['pct', nil, sqreen_request_ratio, utc_now]) Sqreen::Weave.logger.debug { "request sqreen_timer.ratio: #{'%.03f' % (sqreen_request_ratio / 100.0)}" } if Sqreen::Weave.logger.debug? if request[:timed_level] >= 2 tallies = Hash.new(0.0) request[:timed_callbacks].each do |timer| duration = timer.duration timer.tag =~ /weave,rule=(.*)$/ && rule = $1 next unless rule whence = case timer.tag when /@before/ then 'pre' when /@after/ then 'post' when /@raised/ then 'failing' end next unless whence metric_name = "req.sq.#{rule}.#{whence}" tallies[metric_name] += duration end tallies.each do |metric_name, duration| metrics_engine.update(metric_name, now, nil, duration * 1000) # Sqreen.observations_queue.push([metric_name, nil, duration * 1000, utc_now]) end duration = request[:timed_hooks].sum(&:duration) metrics_engine.update('req.sq.hook.overhead', now, nil, duration * 1000) # Sqreen.observations_queue.push(['req.sq.hook.overhead', nil, duration * 1000, utc_now]) end # shrinkwrap_timer.stop # duration = shrinkwrap_timer.duration # metrics_engine.update('sq.shrinkwrap', now, nil, duration * 1000) end end.install ### globally declare instrumentation ready Sqreen.instrumentation_ready = true Sqreen::Weave.logger.info { "Instrumentation activated" } end # needed by Sqreen::Runner def remove_all_callbacks Sqreen.instrumentation_ready = false Sqreen::Weave.logger.info { "Instrumentation deactivated" } loop do hook = @hooks.pop break unless hook Sqreen::Weave.logger.debug { "hook.deinstrument: #{hook}" } hook.uninstall hook.clear end end # needed by #instrument! def add_callback(rule, callback, strategy) Sqreen::Weave.logger.debug { "Adding rule: #{rule} callback: #{callback}" } klass = callback.klass method = callback.method if (call_count = ENV['SQREEN_DEBUG_CALL_COUNT']) call_count = JSON.parse(call_count) if callback.respond_to?(:rule_name) && call_count.key?(callback.rule_name) count = call_count[callback.rule_name] Sqreen::Weave.logger.debug { "override rule: #{callback.rule_name} call_count: #{count.inspect}" } callback.instance_eval { @call_count_interval = call_count[callback.rule_name] } end end if Sqreen::Graft::HookPoint.new("#{klass}.#{method}").exist? hook_point = "#{klass}.#{method}" elsif Sqreen::Graft::HookPoint.new("#{klass}##{method}").exist? hook_point = "#{klass}##{method}" end return if hook_point.nil? priority = callback.priority || 100 block = callback.respond_to?(:block) ? callback.block : true ignore = -> { callback.whitelisted? } if callback.respond_to?(:whitelisted?) hook = Sqreen::Graft::Hook[hook_point, strategy] hook.add do if callback.pre? before(rule, rank: priority, mandatory: !callback.overtimeable, flow: block, ignore: ignore) do |call, b| next unless Thread.current[:sqreen_http_request] i = call.instance a = call.args r = call.remaining begin ret = callback.pre(i, a, r) rescue StandardError => e Sqreen::Weave.logger.warn { "#{rule} klass=#{callback.klass} method=#{callback.method} when=#pre instance=#{i} => exception=#{e}" } if callback.respond_to?(:record_exception) callback.record_exception(e) else Sqreen::RemoteException.record(e) end end next if ret.nil? || !ret.is_a?(Hash) throw_val = case ret[:status] when :skip, 'skip' b.return(ret[:new_return_value]).break! if ret.key?(:new_return_value) when :modify_args, 'modify_args' b.args(ret[:args]) when :raise, 'raise' if ret.key?(:exception) b.raise(ret[:exception]) else b.raise(Sqreen::AttackBlocked.new("Sqreen blocked a security threat (type: #{callback.rule_name}). No action is required.")) end end next unless throw_val throw_val.break! if ret[:skip_rem_cbs] throw(b, throw_val) end end if callback.post? after(rule, rank: -priority, mandatory: !callback.overtimeable, flow: block, ignore: ignore) do |call, b| next unless Thread.current[:sqreen_http_request] i = call.instance v = call.returned a = call.args r = call.remaining begin ret = callback.post(v, i, a, r) rescue StandardError => e Sqreen::Weave.logger.warn { "#{rule} klass=#{callback.klass} method=#{callback.method} when=#post instance=#{i} => exception=#{e}" } if callback.respond_to?(:record_exception) callback.record_exception(e) else Sqreen::RemoteException.record(e) end end case ret[:status] when :override, 'override' throw(b, b.return(ret[:new_return_value])) if ret.key?(:new_return_value) when :raise, 'raise' throw(b, b.raise(ret[:exception])) if ret.key?(:exception) throw(b, b.raise(Sqreen::AttackBlocked.new("Sqreen blocked a security threat (type: #{callback.rule_name}). No action is required."))) end unless ret.nil? || !ret.is_a?(Hash) end end if callback.failing? raised(rule, rank: priority, mandatory: !callback.overtimeable, flow: block, ignore: ignore) do |call, b| next unless Thread.current[:sqreen_http_request] i = call.instance e = call.raised a = call.args r = call.remaining begin ret = callback.failing(e, i, a, r) rescue StandardError => e Sqreen::Weave.logger.warn { "#{rule} klass=#{callback.klass} method=#{callback.method} when=#failing instance=#{i} => exception=#{e}" } if callback.respond_to?(:record_exception) callback.record_exception(e) else Sqreen::RemoteException.record(e) end end throw(b, b.raise(e)) if ret.nil? || !ret.is_a?(Hash) case ret[:status] when :override, 'override' throw(b, b.return(ret[:new_return_value])) if ret.key?(:new_return_value) when :retry, 'retry' throw(b, b.retry) when :raise, 'raise' throw(b, b.raise(ret[:exception])) if ret.key?(:exception) throw(b, b.raise(Sqreen::AttackBlocked.new("Sqreen blocked a security threat (type: #{callback.rule_name}). No action is required."))) when :reraise, 'reraise' throw(b, b.raise(e)) else throw(b, b.raise(e)) end unless ret.nil? || !ret.is_a?(Hash) end end end.install hook end # needed by Sqreen::Rules.cb_from_rule def valid_method?(klass, method) if Sqreen::Graft::HookPoint.new("#{klass}.#{method}").exist? Sqreen::Weave.logger.debug { "HookPoint found: #{klass}.#{method}" } true elsif Sqreen::Graft::HookPoint.new("#{klass}##{method}").exist? Sqreen::Weave.logger.debug { "HookPoint found: #{klass}##{method}" } true else Sqreen::Weave.logger.debug { "HookPoint not found: #{klass} #{method}" } false end end # needed by #instrument! def hardcoded_callbacks(framework) [ ### callback for performing sec responses based on ip ### init redefined to implement smartass way to hook it upon the ### framework's middleware #call Sqreen::Rules::RunReqStartActions.new(framework), ### callback for performing sec responses based on user Sqreen::Rules::RunUserActions.new(Sqreen, :identify, 0), ### callback for performing sec responses based on user Sqreen::Rules::RunUserActions.new(Sqreen, :auth_track, 1), ] end end