From 3b4bda89dfaeed1271276f69b2ce44879f577af4 Mon Sep 17 00:00:00 2001 From: rhymes Date: Sun, 7 Apr 2019 21:27:53 +0200 Subject: [PATCH] Upgrade Honeycomb gem, fix and improve RssReader tests (#2319) * Switch from deprecated honeycomb-rails to honeycomb-beeline * Improve error handling, tests and add refactoring * Fix multiple fetching test and add one more The test wasn't actually testing the correct behavior, because the class by default force fetches. It worked because it wasn't reloading the user from the database. * Test that Honeycomb's client is doing its thing * Use some defensive programming to avoid any possible problem during shutdown * Fix typo * Use the new API to add fields to the current measured event * Use default instrumentation and add user info to event * Replace user.email with user.username, less personal data around * Use mocking instead of calling Honeycomb.init * Freeze time before traveling * Remove a flaky test dependent on rand --- Gemfile | 17 +-- Gemfile.lock | 17 ++- app/controllers/application_controller.rb | 5 - app/services/rss_reader.rb | 139 ++++++++++-------- config.ru | 10 ++ config/initializers/honeycomb.rb | 27 ---- config/initializers/shutdown.rb | 4 + lib/instrumentation.rb | 20 ++- .../gets_articles_for_user.approved.txt | 0 spec/services/rss_reader_spec.rb | 108 ++++++++++++-- 10 files changed, 224 insertions(+), 123 deletions(-) delete mode 100644 config/initializers/honeycomb.rb create mode 100644 config/initializers/shutdown.rb rename spec/fixtures/approvals/rssreader/{get_all_articles => fetch_user}/gets_articles_for_user.approved.txt (100%) diff --git a/Gemfile b/Gemfile index 9096f083c..9ed525052 100644 --- a/Gemfile +++ b/Gemfile @@ -14,8 +14,8 @@ end gem "actionpack-action_caching", "~> 1.2" gem "active_record_union", "~> 1.3" -gem "acts-as-taggable-on", "~> 6.0" gem "acts_as_follower", github: "thepracticaldev/acts_as_follower", branch: "master" +gem "acts-as-taggable-on", "~> 6.0" gem "addressable", "~> 2.5", ">= 2.5.2" gem "administrate", "~> 0.11" gem "ahoy_email", "~> 0.5" @@ -28,8 +28,8 @@ gem "aws-sdk-lambda", "~> 1.16" # Just Lambda. For more, install aws-sdk gem gem "bootsnap", ">= 1.1.0", require: false gem "bourbon", "~> 5.1" gem "buffer", "~> 0.1" -gem "carrierwave", "~> 1.3" gem "carrierwave-bombshelter", "~> 0.2" +gem "carrierwave", "~> 1.3" gem "cloudinary", "~> 1.11" gem "counter_culture", "~> 2.1" gem "csv_shaper", "~> 1.3" @@ -42,8 +42,8 @@ gem "dry-struct", "~> 0.6" gem "email_validator", "~> 2.0" gem "emoji_regex", "~> 1.0" gem "envied", "~> 0.9" -gem "fastly", "~> 1.15" gem "fastly-rails", "~> 0.8" +gem "fastly", "~> 1.15" gem "feedjira", "~> 2.2" gem "figaro", "~> 1.1" gem "fog", "~> 1.41" @@ -51,32 +51,31 @@ gem "front_matter_parser", "~> 0.2" gem "gemoji", "~> 3.0.0" gem "gibbon", "~> 3.2" gem "google-api-client", "~> 0.27" -gem "honeycomb-rails" +gem 'honeycomb-beeline', "~> 0.7.0" gem "html_truncator", "~> 0.4" gem "httparty", "~> 0.16" gem "inline_svg", "~> 1.3" gem "jbuilder", "~> 2.8" gem "jquery-rails", "~> 4.3" gem "kaminari", "~> 1.1" -gem "libhoney", "~> 1.12" gem "liquid", "~> 4.0" gem "nokogiri", "~> 1.10" gem "octokit", "~> 4.13" -gem "omniauth", "~> 1.9" gem "omniauth-github", "~> 1.3" gem "omniauth-twitter", "~> 1.4" +gem "omniauth", "~> 1.9" gem "pg", "~> 1.1" -gem "pry", "~> 0.12" gem "pry-rails", "~> 0.3" +gem "pry", "~> 0.12" gem "puma", "~> 3.12" gem "pundit", "~> 2.0" -gem "pusher", "~> 1.3" gem "pusher-push-notifications", "~> 1.0" +gem "pusher", "~> 1.3" gem "rack-host-redirect", "~> 1.3" gem "rack-timeout", "~> 0.5" -gem "rails", "~> 5.2", ">= 5.2.3" gem "rails-assets-airbrake-js-client", "~> 1.5", source: "https://rails-assets.org" gem "rails-observers", "~> 0.1" +gem "rails", "~> 5.2", ">= 5.2.3" gem "recaptcha", "~> 4.13", require: "recaptcha/rails" gem "redcarpet", "~> 3.4" gem "reverse_markdown", "~> 1.1" diff --git a/Gemfile.lock b/Gemfile.lock index ddf0f2ee7..0e2c6bc68 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -59,6 +59,8 @@ GEM activemodel (= 5.2.3) activesupport (= 5.2.3) arel (>= 9.0) + activerecord-honeycomb (0.4.0) + libhoney activestorage (5.2.3) actionpack (= 5.2.3) activerecord (= 5.2.3) @@ -330,6 +332,8 @@ GEM i18n (>= 0.7) faraday (0.15.4) multipart-post (>= 1.2, < 3) + faraday-honeycomb (0.3.1) + libhoney (>= 1.5.0) faraday_middleware (0.13.1) faraday (>= 0.7.4, < 1.0) fastimage (2.1.1) @@ -544,9 +548,11 @@ GEM hashie (3.6.0) heapy (0.1.4) hkdf (0.3.0) - honeycomb-rails (0.8.1) - libhoney (>= 1.9) - rails (>= 3.0.0) + honeycomb-beeline (0.7.0) + activerecord-honeycomb (>= 0.4.0) + faraday-honeycomb (>= 0.3.0) + libhoney (>= 1.8.1) + rack-honeycomb (>= 0.4.0) html_tokenizer (0.0.7) html_truncator (0.4.2) nokogiri (~> 1.5) @@ -705,6 +711,8 @@ GEM pusher-signature (0.1.8) raabro (1.1.6) rack (2.0.6) + rack-honeycomb (0.5.0) + libhoney (>= 1.5.0) rack-host-redirect (1.3.0) rack rack-protection (2.0.5) @@ -1033,7 +1041,7 @@ DEPENDENCIES guard (~> 2.15) guard-livereload (~> 2.5) guard-rspec (~> 4.7) - honeycomb-rails + honeycomb-beeline (~> 0.7.0) html_truncator (~> 0.4) httparty (~> 0.16) inline_svg (~> 1.3) @@ -1041,7 +1049,6 @@ DEPENDENCIES jquery-rails (~> 4.3) kaminari (~> 1.1) launchy (~> 2.4) - libhoney (~> 1.12) liquid (~> 4.0) memory_profiler (~> 0.9) nakayoshi_fork diff --git a/app/controllers/application_controller.rb b/app/controllers/application_controller.rb index 334e3f68a..20a5048f7 100644 --- a/app/controllers/application_controller.rb +++ b/app/controllers/application_controller.rb @@ -78,9 +78,4 @@ class ApplicationController < ActionController::Base def touch_current_user current_user.touch end - - def append_info_to_payload(payload) - super(payload) - append_to_honeycomb(request, self.class.name) - end end diff --git a/app/services/rss_reader.rb b/app/services/rss_reader.rb index abc6840b1..41298fb9b 100644 --- a/app/services/rss_reader.rb +++ b/app/services/rss_reader.rb @@ -1,7 +1,3 @@ -require "nokogiri" -require "httparty" -require "securerandom" - class RssReader def self.get_all_articles(force = true) new.get_all_articles(force) @@ -13,15 +9,18 @@ class RssReader def get_all_articles(force = true) User.where.not(feed_url: [nil, ""]).find_each do |user| - next if force == false && (rand(2) == 1 || user.feed_fetched_at > 15.minutes.ago) # Don't fetch every time. + # unless forced, fetch sparingly + next if force == false && (rand(2) == 1 || user.feed_fetched_at > 15.minutes.ago) create_articles_for_user(user) end end def fetch_user(user) - Thread.current[:request_id] = @request_id - Thread.current[:span_id] = @request_id + # add request_id to thread current variables to aid Honeycomb instrumentation + Thread.current[:request_id] = request_id + Thread.current[:span_id] = request_id + create_articles_for_user(user) end @@ -33,26 +32,34 @@ class RssReader private + attr_reader :request_id + def create_articles_for_user(user) with_span("create_articles_for_user", user_id: user.id, username: user.username) do |metadata| user.update_column(:feed_fetched_at, Time.current) feed = fetch_rss(user.feed_url.strip) + metadata[:feed_length] = feed.entries.length if feed&.entries + feed.entries.reverse_each do |item| make_from_rss_item(item, user, feed) rescue StandardError => e - log_error("RssReaderError: occurred while creating article for", - user: user.username, - feed_url: user.feed_url, - item_count: get_item_count_error(feed), - error: e) + log_error( + "RssReaderError: occurred while creating article", + user: user.username, + feed_url: user.feed_url, + item_count: get_item_count_error(feed), + error: e, + ) end rescue StandardError => e - log_error("RssReaderError: occurred while fetch feed for", - user: user.username, - feed_url: user.feed_url, - item_count: get_item_count_error(feed), - error: e) + log_error( + "RssReaderError: occurred while fetching feed", + user: user.username, + feed_url: user.feed_url, + item_count: get_item_count_error(feed), + error: e, + ) end end @@ -76,33 +83,29 @@ class RssReader end def make_from_rss_item(item, user, feed) - with_span("make_from_rss_item", - item_id: item.entry_id, - item_title: item.title, - item_summary_size: item.summary&.size) do |metadata| - return if medium_reply?(item) || article_exist?(user, item) + with_span( + "make_from_rss_item", + item_id: item.entry_id, + item_title: item.title, + item_summary_size: item.summary&.size, + ) do |metadata| + + return if medium_reply?(item) || article_exists?(user, item) - article_params = { - feed_source_url: feed_source_url = item.url.strip.split("?source=")[0], - user_id: user.id, - published_at: item.published, - published_from_feed: true, - show_comments: true, - # body_markdown: assemble_body_markdown(item, user, feed, feed_source_url), - body_markdown: RssReader::Assembler.call(item, user, feed, feed_source_url), - organization_id: user.organization_id.presence - } article = with_timer("save_article", metadata) do - Article.create!(article_params) + feed_source_url = item.url.strip.split("?source=")[0] + Article.create!( + feed_source_url: feed_source_url, + user_id: user.id, + published_at: item.published, + published_from_feed: true, + show_comments: true, + body_markdown: RssReader::Assembler.call(item, user, feed, feed_source_url), + organization_id: user.organization_id.presence, + ) end - return unless Rails.env.production? - SlackBot.delay.ping( - "New Article Retrieved via RSS: #{article.title}\nhttps://dev.to#{article.path}", - channel: "activity", - username: "article_bot", - icon_emoji: ":robot_face:", - ) + send_slack_notification(article) end end @@ -125,27 +128,46 @@ class RssReader content.include?(title) end - def article_exist?(user, item) - user.articles.find_by("title = ? OR feed_source_url = ?", item.title.strip.gsub('"', '\"'), item.url.strip.split("?source=")[0]) + def article_exists?(user, item) + title = item.title.strip.gsub('"', '\"') + feed_source_url = item.url.strip.split("?source=")[0] + relation = user.articles + relation.where(title: title).or(relation.where(feed_source_url: feed_source_url)).exists? + end + + def send_slack_notification(article) + return unless Rails.env.production? + + SlackBot.delay.ping( + "New Article Retrieved via RSS: #{article.title}\nhttps://dev.to#{article.path}", + channel: "activity", + username: "article_bot", + icon_emoji: ":robot_face:", + ) end def log_error(error_msg, metadata) - logger = Logger.new(STDOUT) - parts = metadata.map { |k, v| [k.upcase.to_s.sub(/_/, "-"), v].join(": ") } - parts = parts.unshift(error_msg) - logger.info(parts.join(" ")) + # giving the error message a resemblance of structured logging + parts = metadata.map { |k, v| [k, v].join("=") } + parts = parts.unshift("#{error_msg}:") + Rails.logger.error(parts.join(" ")) + + # log error to Honeycomb if initialized + return unless Honeycomb.client - # log error to Honeycomb ev = Honeycomb.client.event ev.add(metadata) ev.add_field("error_msg", error_msg) - ev.add_field("trace.trace_id", @request_id) - parent_id = Thread.current[:span_id] || @request_id - ev.add_field("trace.parent_id", parent_id) + ev.add_field("trace.trace_id", request_id) + ev.add_field("trace.parent_id", Thread.current[:span_id] || request_id) ev.add_field("trace.span_id", SecureRandom.uuid) ev.send end + # NOTE: honeycomb-beeline makes "with_span" theoretically obsolete, + # unfortunately there's a bug that prevents the gem to add fields after a + # a span has been initiated, so for now we'll keep this code in. + # see # This wrapper takes a span name, some optional metadata, and a block; then # emits a "span" to Honeycomb as part of the trace begun in the RequestTracer # middleware. @@ -155,13 +177,13 @@ class RssReader # into the block. def with_span(name, metadata = nil) trace_id = Thread.current[:request_id] - return yield({}) unless trace_id + return yield({}) unless trace_id && Honeycomb.client - id = SecureRandom.uuid - start = Time.new + current_span_id = SecureRandom.uuid + start = Time.current data = { name: name, - "trace.span_id": id, + "trace.span_id": current_span_id, "trace.trace_id": trace_id, service_name: "rss_reader" } @@ -172,10 +194,10 @@ class RssReader # Set the current span ID before invoking the provided block, then capture # the return value to return after emitting the Honeycomb event. - Thread.current[:span_id] = id + Thread.current[:span_id] = span_id ret = yield data - data[:duration_ms] = (Time.new - start) * 1000 + data[:duration_ms] = (Time.current - start) * 1000 data.merge!(metadata) if metadata # log event to Honeycomb @@ -190,10 +212,9 @@ class RssReader end def with_timer(name, data) - start = Time.new + start = Time.current ret = yield - data[name + "_dur_ms"] = (Time.new - start) * 1000 if data - + data[name + "_dur_ms"] = (Time.current - start) * 1000 if data ret end end diff --git a/config.ru b/config.ru index 193e5fed8..eee1402bf 100644 --- a/config.ru +++ b/config.ru @@ -1,4 +1,14 @@ # This file is used by Rack-based servers to start the application. +# Honeycomb must be initialized before the Rails app starts +# see for details +require "honeycomb-beeline" +Honeycomb.init( + writekey: ENV["HONEYCOMB_API_KEY"], + # NOTE: dataset should probably be set using "HONEYCOMB_DATASET" env, + # to avoid hardcoding "dev.to" as a name + dataset: "dev.to-#{ENV['RAILS_ENV']}", +) + require ::File.expand_path("../config/environment", __FILE__) run Rails.application diff --git a/config/initializers/honeycomb.rb b/config/initializers/honeycomb.rb deleted file mode 100644 index bdda956c8..000000000 --- a/config/initializers/honeycomb.rb +++ /dev/null @@ -1,27 +0,0 @@ -require "libhoney" - -module Honeycomb - class << self - attr_accessor :client - end -end - -key = ApplicationConfig["HONEYCOMB_API_KEY"] -dataset = "dev.to-#{Rails.env}" - -Honeycomb.client = if Rails.env.development? || Rails.env.test? - Libhoney::NullClient.new - else - Libhoney::Client.new( - writekey: key, - dataset: dataset, - user_agent_addition: HoneycombRails::USER_AGENT_SUFFIX, - ) - end - -HoneycombRails.configure do |conf| - conf.writekey = key - conf.dataset = dataset - conf.db_dataset = "dev.to-db-#{Rails.env}" - conf.client = Honeycomb.client -end diff --git a/config/initializers/shutdown.rb b/config/initializers/shutdown.rb new file mode 100644 index 000000000..59c0d78aa --- /dev/null +++ b/config/initializers/shutdown.rb @@ -0,0 +1,4 @@ +# adding an exit hook to properly shutdown/close third party clients +at_exit do + Honeycomb.shutdown if defined?(Honeycomb) && Honeycomb.respond_to?(:shutdown) +end diff --git a/lib/instrumentation.rb b/lib/instrumentation.rb index b43c9d793..a433e77d4 100644 --- a/lib/instrumentation.rb +++ b/lib/instrumentation.rb @@ -1,22 +1,26 @@ +require "rack/honeycomb/middleware" + module Instrumentation + def self.included(base) + base.before_action :add_user_info_to_honeycomb_event + end + def add_param_context(*keys) keys.each do |key| - honeycomb_metadata[key] = params[key] + Rack::Honeycomb.add_field(request.env, key, params[key]) end end def add_context(metadata) metadata.each do |key, value| - honeycomb_metadata[key] = value + Rack::Honeycomb.add_field(request.env, key, value) end end - def append_to_honeycomb(request, controller_name) - return if honeycomb_metadata.nil? + def add_user_info_to_honeycomb_event + return unless current_user - honeycomb_metadata["trace.trace_id"] = request.request_id - honeycomb_metadata["trace.span_id"] = request.request_id - honeycomb_metadata[:service_name] = "rails" - honeycomb_metadata[:name] = controller_name + Rack::Honeycomb.add_field(request.env, "user.id", current_user.id) + Rack::Honeycomb.add_field(request.env, "user.username", current_user.username) end end diff --git a/spec/fixtures/approvals/rssreader/get_all_articles/gets_articles_for_user.approved.txt b/spec/fixtures/approvals/rssreader/fetch_user/gets_articles_for_user.approved.txt similarity index 100% rename from spec/fixtures/approvals/rssreader/get_all_articles/gets_articles_for_user.approved.txt rename to spec/fixtures/approvals/rssreader/fetch_user/gets_articles_for_user.approved.txt diff --git a/spec/services/rss_reader_spec.rb b/spec/services/rss_reader_spec.rb index de9f40ca8..c6cb6ffae 100644 --- a/spec/services/rss_reader_spec.rb +++ b/spec/services/rss_reader_spec.rb @@ -6,12 +6,36 @@ vcr_option = { allow_playback_repeats: "true" } +class HoneycombEventStub + attr_reader :data + + def initialize + @data = {} + end + + def add(metadata) + @data.merge!(metadata) + end + + def add_field(key, value) + @data[key] = value + end +end + RSpec.describe RssReader, vcr: vcr_option do let(:link) { "https://medium.com/feed/@vaidehijoshi" } let(:nonmedium_link) { "https://circleci.com/blog/feed.xml" } let(:nonpermanent_link) { "https://medium.com/feed/@macsiri/" } let(:rss_data) { RSS::Parser.parse(HTTParty.get(link).body, false) } + before do + # Honeycomb.init has too many side effects during testing, so we mock the client + event = HoneycombEventStub.new + allow(event).to receive(:send) + client_double = instance_double("Libhoney::TestClient", event: event, events: [event]) + allow(Honeycomb).to receive(:client) { client_double } + end + describe "#get_all_articles" do before do [link, nonmedium_link, nonpermanent_link].each do |feed_url| @@ -43,17 +67,41 @@ RSpec.describe RssReader, vcr: vcr_option do expect(User.find_by(feed_url: nonpermanent_link).feed_fetched_at).to be > 2.minutes.ago end - it "does not refetch same user over and over" do + it "does refetch same user over and over by default" do user = User.find_by(feed_url: nonpermanent_link) - user.update_column(:feed_fetched_at, Time.current) - fetched_at_time = user.feed_fetched_at - sleep(1) - described_class.new.get_all_articles - described_class.new.get_all_articles - described_class.new.get_all_articles - described_class.new.get_all_articles - described_class.new.get_all_articles - expect(user.feed_fetched_at).to eq(fetched_at_time) + Timecop.freeze(Time.current) do + user.update_column(:feed_fetched_at, Time.current) + fetched_at_time = user.reload.feed_fetched_at + # travel a few seconds in the future to simulate a new time + 3.times do |i| + Timecop.travel((i + 5).seconds.from_now) { described_class.new.get_all_articles } + end + expect(user.reload.feed_fetched_at > fetched_at_time).to be(true) + end + end + + it "logs an article creation error" do + reader = described_class.new + allow(reader).to receive(:make_from_rss_item).and_raise(StandardError) + allow(Rails.logger).to receive(:error) + reader.get_all_articles + expect(Rails.logger).to have_received(:error).at_least(:once) + end + + it "logs a fetching error" do + reader = described_class.new + allow(reader).to receive(:fetch_rss).and_raise(StandardError) + allow(Rails.logger).to receive(:error) + reader.get_all_articles + expect(Rails.logger).to have_received(:error).at_least(:once) + end + end + + describe "#fetch_user" do + before do + [link, nonmedium_link, nonpermanent_link].each do |feed_url| + create(:user, feed_url: feed_url) + end end it "gets articles for user" do @@ -66,6 +114,46 @@ RSpec.describe RssReader, vcr: vcr_option do described_class.new.fetch_user(User.first) expect(Article.all.map(&:featured_number).uniq).to eq([nil]) end + + it "logs an article creation error on the standard logger" do + reader = described_class.new + allow(reader).to receive(:make_from_rss_item).and_raise(StandardError) + allow(Rails.logger).to receive(:error) + reader.fetch_user(User.first) + expect(Rails.logger).to have_received(:error).at_least(:once) + end + + it "logs an article creation error on the observability tool" do + reader = described_class.new + allow(reader).to receive(:make_from_rss_item).and_raise(StandardError) + reader.fetch_user(User.first) + + expected_observable_fields = [ + :user, :feed_url, :item_count, :error, + "error_msg", "trace.trace_id", "trace.parent_id", "trace.span_id" + ] + expect(Honeycomb.client.events.first.data.keys).to eq(expected_observable_fields) + end + + it "logs a fetching error on the standard logger" do + reader = described_class.new + allow(reader).to receive(:fetch_rss).and_raise(StandardError) + allow(Rails.logger).to receive(:error) + reader.fetch_user(User.first) + expect(Rails.logger).to have_received(:error).at_least(:once) + end + + it "logs a fetching error on the observability tool" do + reader = described_class.new + allow(reader).to receive(:fetch_rss).and_raise(StandardError) + reader.fetch_user(User.first) + + expected_observable_fields = [ + :user, :feed_url, :item_count, :error, + "error_msg", "trace.trace_id", "trace.parent_id", "trace.span_id" + ] + expect(Honeycomb.client.events.first.data.keys).to eq(expected_observable_fields) + end end describe "#valid_feed_url?" do