From d502c790048a5dd0a5c33d34dbd5dba5b96eaa26 Mon Sep 17 00:00:00 2001
From: Agis Anastasopoulos <a@xz0.org>
Date: Sun, 2 Aug 2020 21:44:18 +0300
Subject: [PATCH] Implement Sentry integration

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).

Current events emitted:

- [warning] no previous timings were found (aka. scheduling is random,
  build time will suffer)
- [info] slow files were detected and will be split
- [info] new/untimed job received
- [error] the split shell command failed, slow files won't be split
  (i.e. build time will suffer)

The above are still also printed to the standard output of the worker.

Closes #8
---
 README.md            | 11 +++++++++
 lib/rspecq.rb        |  1 +
 lib/rspecq/worker.rb | 53 +++++++++++++++++++++++++++++++++++---------
 rspecq.gemspec       |  1 +
 4 files changed, 55 insertions(+), 11 deletions(-)

diff --git a/README.md b/README.md
index 32ac804..1fb8a00 100644
--- a/README.md
+++ b/README.md
@@ -56,6 +56,17 @@ OPTIONS:
     -v, --version                    Print the version and exit.
 ```
 
+### Sentry integration
+
+RSpecQ can optionally emit build events to a
+[Sentry](https://sentry.io) project by setting the
+[`SENTRY_DSN`](https://github.com/getsentry/raven-ruby#raven-only-runs-when-sentry_dsn-is-set)
+environment variable.
+
+This is convenient for monitoring important warnings/errors that may impact
+build times, such as the fact that no previous timings were found and
+therefore job scheduling was effectively random for a particular build.
+
 
 ## How it works
 
diff --git a/lib/rspecq.rb b/lib/rspecq.rb
index 4a97e2a..a96c8fa 100644
--- a/lib/rspecq.rb
+++ b/lib/rspecq.rb
@@ -1,4 +1,5 @@
 require "rspec/core"
+require "sentry-raven"
 
 module RSpecQ
   # Failed examples will be retried by (usually) another worker up to
diff --git a/lib/rspecq/worker.rb b/lib/rspecq/worker.rb
index 4a3a24f..42a334d 100644
--- a/lib/rspecq/worker.rb
+++ b/lib/rspecq/worker.rb
@@ -95,10 +95,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
 
@@ -107,7 +108,13 @@ 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,
+          file_split_threshold: file_split_threshold
+        )
       end
 
       # prepare jobs to run
@@ -120,7 +127,7 @@ def try_publish_queue!(queue)
 
       jobs = jobs.each_with_object({}) do |j, h|
         # heuristic: put untimed jobs in the middle of the queue
-        puts "New/untimed job: #{j}" if timings[j].nil?
+        log_event("New/untimed job: #{j}", "info", job: j) if timings[j].nil?
         h[j] = timings[j] || default_timing
       end
 
@@ -161,14 +168,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)
+        puts out
+        puts $?.inspect
+        rspec_output = begin
+          JSON.parse(out)
         rescue JSON::ParserError
-          puts out
+          out
         end
+
+        log_event(
+          "Error splitting slow files! Falling back to regular scheduling",
+          "error",
+          rspec_output: rspec_output,
+          cmd_result: $?.inspect,
+        )
+
+        pp rspec_output
         puts
 
         return files
@@ -185,5 +200,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"