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