From 3364dd021373b59497b8739acdf8d181683a9838 Mon Sep 17 00:00:00 2001 From: Agis Anastasopoulos Date: Sun, 2 Aug 2020 21:44:18 +0300 Subject: [PATCH 1/2] Implement Sentry integration This patch adds support for Workers to emit various RSpecQ internal events to a Sentry[1] instance. Reporting to Sentry is opt-in and is enabled by setting the SENTRY_DSN environment variable (see https://github.com/getsentry/raven-ruby#raven-only-runs-when-sentry_dsn-is-set). If SENTRY_DSN is not set this is a noop. Events emitted: - [error] the spec file split command failed; slow spec files files will be scheduled as a whole so build times will be negatively impacted - [warning] no previous timings were found in Redis; scheduling will be random so build times will be negatively impacted - [info] slow files were detected and will be split, including the actual filenames The above are still printed to the standard output of the worker. Closes #8 [1] https://sentry.io --- bin/rspecq | 2 +- lib/rspecq.rb | 1 + lib/rspecq/worker.rb | 56 ++++++++++++++++++++++++++++++++++---------- rspecq.gemspec | 1 + 4 files changed, 46 insertions(+), 14 deletions(-) diff --git a/bin/rspecq b/bin/rspecq index 0143fa4..2c10473 100755 --- a/bin/rspecq +++ b/bin/rspecq @@ -24,7 +24,7 @@ OptionParser.new do |o| BANNER o.separator "" - o.separator "OPTIONS:" + o.separator "OPTIONS:" o.on("-b", "--build ID", "A unique identifier for the build. Should be " \ "common among workers participating in the same build.") do |v| diff --git a/lib/rspecq.rb b/lib/rspecq.rb index aaa4c86..1d75355 100644 --- a/lib/rspecq.rb +++ b/lib/rspecq.rb @@ -1,4 +1,5 @@ require "rspec/core" +require "sentry-raven" module RSpecQ # If a worker haven't executed an example for more than WORKER_LIVENESS_SEC diff --git a/lib/rspecq/worker.rb b/lib/rspecq/worker.rb index ce29792..f93b9b9 100644 --- a/lib/rspecq/worker.rb +++ b/lib/rspecq/worker.rb @@ -17,7 +17,7 @@ class Worker # Retry failed examples up to N times (with N being the supplied value) # before considering them legit failures - # + # # Defaults to 3 attr_accessor :max_requeues @@ -102,10 +102,11 @@ def try_publish_queue!(queue) timings = queue.timings if timings.empty? - # TODO: should be a warning reported somewhere (Sentry?) q_size = queue.publish(files_to_run.shuffle) - puts "WARNING: No timings found! Published queue in " \ - "random order (size=#{q_size})" + log_event( + "No timings found! Published queue in random order (size=#{q_size})", + "warning" + ) return end @@ -114,7 +115,12 @@ def try_publish_queue!(queue) end.map(&:first) & files_to_run if slow_files.any? - puts "Slow files (threshold=#{file_split_threshold}): #{slow_files}" + log_event( + "Slow files detected (threshold=#{file_split_threshold}): #{slow_files}", + "info", + slow_files: slow_files, + slow_files_count: slow_files.count, + ) end # prepare jobs to run @@ -168,14 +174,22 @@ def files_to_example_ids(files) out = `#{cmd}` if !$?.success? - # TODO: emit warning to Sentry - puts "WARNING: Error splitting slow files; falling back to regular scheduling:" - - begin - pp JSON.parse(out) - rescue JSON::ParserError - puts out - end + puts out + puts $?.inspect + rspec_output = begin + JSON.parse(out) + rescue JSON::ParserError + out + end + + log_event( + "Failed to split slow files, falling back to regular scheduling", + "error", + rspec_output: rspec_output, + cmd_result: $?.inspect, + ) + + pp rspec_output puts return files @@ -192,5 +206,21 @@ def relative_path(job) def elapsed(since) Process.clock_gettime(Process::CLOCK_MONOTONIC) - since end + + def log_event(msg, level, additional={}) + puts msg + + Raven.capture_message(msg, level: level, extra: { + build: @build_id, + worker: @worker_id, + queue: queue.inspect, + files_or_dirs_to_run: @files_or_dirs_to_run, + populate_timings: populate_timings, + file_split_threshold: file_split_threshold, + heartbeat_updated_at: @heartbeat_updated_at, + object: self.inspect, + pid: Process.pid, + }.merge(additional)) + end end end diff --git a/rspecq.gemspec b/rspecq.gemspec index c4824a6..9a80bdc 100644 --- a/rspecq.gemspec +++ b/rspecq.gemspec @@ -19,6 +19,7 @@ Gem::Specification.new do |s| end s.add_dependency "redis" + s.add_dependency "sentry-raven" s.add_development_dependency "rake" s.add_development_dependency "pry-byebug" From 42d20e75a6229c5b50a70c25f9146335cf8ea403 Mon Sep 17 00:00:00 2001 From: Agis Anastasopoulos Date: Mon, 3 Aug 2020 12:56:26 +0300 Subject: [PATCH 2/2] worker: Redirect stderr of split command to stdout Usually RSpec prints errors to stderr, so we have to grab it too in order to display a helpful error message in case this command fails. Ideally we'd do this with popen3, but this is good enough for now, considering #6. --- lib/rspecq/worker.rb | 13 ++++++------- 1 file changed, 6 insertions(+), 7 deletions(-) diff --git a/lib/rspecq/worker.rb b/lib/rspecq/worker.rb index f93b9b9..8023e69 100644 --- a/lib/rspecq/worker.rb +++ b/lib/rspecq/worker.rb @@ -169,13 +169,11 @@ def reset_rspec_state! # Their errors will be reported in the normal flow, when they're picked up # as jobs by a worker. def files_to_example_ids(files) - # TODO: do this programatically - cmd = "DISABLE_SPRING=1 bundle exec rspec --dry-run --format json #{files.join(' ')}" + cmd = "DISABLE_SPRING=1 bundle exec rspec --dry-run --format json #{files.join(' ')} 2>&1" out = `#{cmd}` + cmd_result = $? - if !$?.success? - puts out - puts $?.inspect + if !cmd_result.success? rspec_output = begin JSON.parse(out) rescue JSON::ParserError @@ -186,11 +184,10 @@ def files_to_example_ids(files) "Failed to split slow files, falling back to regular scheduling", "error", rspec_output: rspec_output, - cmd_result: $?.inspect, + cmd_result: cmd_result.inspect, ) pp rspec_output - puts return files end @@ -207,6 +204,8 @@ def elapsed(since) Process.clock_gettime(Process::CLOCK_MONOTONIC) - since end + # Prints msg to standard output and emits an event to Sentry, if the + # SENTRY_DSN environment variable is set. def log_event(msg, level, additional={}) puts msg