From cff6b5d5894a562e19625d8b3fa4f6e004650bc5 Mon Sep 17 00:00:00 2001 From: Christine Yen Date: Wed, 28 Nov 2018 07:08:27 -0800 Subject: [PATCH] Add Honeycomb gem and initial instrumentation (#695) * Add basic Honeycomb initializers * Add some basic instrumentation, capture basic IDs * Correctly alphabetize Gemfile, embed env in dataset names * Actually reorder Gemfile because I can read * Add custom tracing instrumentation to RssReader * Improve timing/tracing info in RssReader * Even make sure Errors show up in trace if possible * Make sure we capture this as Rails traffic * Swap in dev/test Libhoney::Clients as appropriate * Move context-snagging bits into lib/instrumentation.rb * Merging Gemfile lines seems to be my Achilles heel --- Envfile | 3 + Gemfile | 2 + Gemfile.lock | 7 + app/controllers/application_controller.rb | 6 + app/controllers/chat_channels_controller.rb | 6 + app/controllers/comments_controller.rb | 2 + app/controllers/events_controller.rb | 1 + app/controllers/follows_controller.rb | 1 + app/controllers/reactions_controller.rb | 3 + app/controllers/stories_controller.rb | 4 + app/controllers/users_controller.rb | 2 +- app/labor/rss_reader.rb | 202 ++++++++++++++------ config/initializers/honeycomb.rb | 21 ++ lib/instrumentation.rb | 20 ++ 14 files changed, 224 insertions(+), 56 deletions(-) create mode 100644 config/initializers/honeycomb.rb create mode 100644 lib/instrumentation.rb diff --git a/Envfile b/Envfile index 51b3a5199..abbb12315 100644 --- a/Envfile +++ b/Envfile @@ -94,6 +94,9 @@ variable :GA_TRACKING_ID, :String, default: "Optional" variable :GA_OPTIMIZE_ID, :String, default: "Optional" variable :GA_VIEW_ID, :String, default: "Optional" +# Honeycomb +variable :HONEYCOMB_API_KEY, :String, default: "Optional" + # Mailchimp for mails variable :MAILCHIMP_API_KEY, :String, default: "Optional-valid" variable :MAILCHIMP_NEWSLETTER_ID, :String, default: "Optional" diff --git a/Gemfile b/Gemfile index e66eaf2b5..2f3e88634 100644 --- a/Gemfile +++ b/Gemfile @@ -49,12 +49,14 @@ gem "fog", "~> 1.41" gem "front_matter_parser", "~> 0.2" gem "gibbon", "~> 2.2" gem "google-api-client", "~> 0.25" +gem "honeycomb-rails" gem "html_truncator", "~> 0.4" gem "httparty", "~> 0.16" gem "inline_svg", "~> 1.3" gem "jbuilder", "~> 2.7" gem "jquery-rails", "~> 4.3" gem "kaminari", "~> 1.1" +gem "libhoney", "~> 1.10" gem "liquid", "~> 4.0" gem "nokogiri", "~> 1.8" gem "octokit", "~> 4.12" diff --git a/Gemfile.lock b/Gemfile.lock index 9acd6a0ab..78fc21674 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -495,6 +495,9 @@ GEM hashie (3.5.7) heapy (0.1.3) hkdf (0.3.0) + honeycomb-rails (0.8.0) + libhoney (>= 1.8.1) + rails (>= 3.0.0) html_truncator (0.4.2) nokogiri (~> 1.5) http (3.0.0) @@ -547,6 +550,8 @@ GEM kaminari-core (1.1.1) launchy (2.4.3) addressable (~> 2.3) + libhoney (1.10.1) + http (>= 2.0, < 4.0) liquid (4.0.1) listen (3.1.5) rb-fsevent (~> 0.9, >= 0.9.4) @@ -960,6 +965,7 @@ DEPENDENCIES guard (~> 2.15) guard-livereload (~> 2.5) guard-rspec (~> 4.7) + honeycomb-rails html_truncator (~> 0.4) httparty (~> 0.16) inline_svg (~> 1.3) @@ -967,6 +973,7 @@ DEPENDENCIES jquery-rails (~> 4.3) kaminari (~> 1.1) launchy (~> 2.4) + libhoney (~> 1.10) liquid (~> 4.0) memory_profiler (~> 0.9) nakayoshi_fork diff --git a/app/controllers/application_controller.rb b/app/controllers/application_controller.rb index cb746ef3c..122ac11a6 100644 --- a/app/controllers/application_controller.rb +++ b/app/controllers/application_controller.rb @@ -2,6 +2,7 @@ class ApplicationController < ActionController::Base protect_from_forgery with: :exception, prepend: true include Pundit + include Instrumentation def require_http_auth authenticate_or_request_with_http_basic do |username, password| @@ -70,4 +71,9 @@ 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/controllers/chat_channels_controller.rb b/app/controllers/chat_channels_controller.rb index 900629e75..9f90608dd 100644 --- a/app/controllers/chat_channels_controller.rb +++ b/app/controllers/chat_channels_controller.rb @@ -3,6 +3,7 @@ class ChatChannelsController < ApplicationController after_action :verify_authorized def index + add_param_context(:state) if params[:state] == "unopened" authorize ChatChannel render_unopened_json_response @@ -18,11 +19,13 @@ class ChatChannelsController < ApplicationController def show @chat_channel = ChatChannel.find_by_id(params[:id]) || not_found authorize @chat_channel + add_context(chat_channel_id: @chat_channel.id) end def create authorize ChatChannel @chat_channel = ChatChannelCreationService.new(current_user, params[:chat_channel]).create + add_context(chat_channel_id: @chat_channel.id) if @chat_channel.valid? render json: { status: "success", chat_channel: @chat_channel.to_json(only: %i[channel_name slug]) }, @@ -35,6 +38,7 @@ class ChatChannelsController < ApplicationController def update @chat_channel = ChatChannel.find(params[:id]) authorize @chat_channel + add_context(chat_channel_id: @chat_channel.id) ChatChannelUpdateService.new(@chat_channel, chat_channel_params).update if @chat_channel.valid? render json: { status: "success", @@ -48,6 +52,7 @@ class ChatChannelsController < ApplicationController def open @chat_channel = ChatChannel.find(params[:id]) authorize @chat_channel + add_context(chat_channel_id: @chat_channel.id) membership = @chat_channel.chat_channel_memberships.where(user_id: current_user.id).first membership.update(last_opened_at: 1.seconds.from_now, has_unopened_messages: false) @chat_channel.index! @@ -57,6 +62,7 @@ class ChatChannelsController < ApplicationController def moderate @chat_channel = ChatChannel.find(params[:id]) authorize @chat_channel + add_context(chat_channel_id: @chat_channel.id) command = chat_channel_params[:command].split case command[0] when "/ban" diff --git a/app/controllers/comments_controller.rb b/app/controllers/comments_controller.rb index 3517de2f3..be9664320 100644 --- a/app/controllers/comments_controller.rb +++ b/app/controllers/comments_controller.rb @@ -57,6 +57,8 @@ class CommentsController < ApplicationController authorize Comment raise if RateLimitChecker.new(current_user).limit_by_situation("comment_creation") @comment = Comment.new(permitted_attributes(Comment)) + add_context(commentable_id: @comment.commentable_id, + commentable_type: @comment.commentable_type) @comment.user_id = current_user.id if @comment.save if params[:checked_code_of_conduct].present? && !current_user.checked_code_of_conduct diff --git a/app/controllers/events_controller.rb b/app/controllers/events_controller.rb index 94358b0ea..1bde6ea37 100644 --- a/app/controllers/events_controller.rb +++ b/app/controllers/events_controller.rb @@ -11,5 +11,6 @@ class EventsController < ApplicationController def show @event = Event.find_by(slug: params[:id]) + add_context(event_id: @event.id) end end diff --git a/app/controllers/follows_controller.rb b/app/controllers/follows_controller.rb index f1f66f920..255837509 100644 --- a/app/controllers/follows_controller.rb +++ b/app/controllers/follows_controller.rb @@ -23,6 +23,7 @@ class FollowsController < ApplicationController else User.find(params[:followable_id]) end + add_param_context(:followable_type, :followable_id, :verb) @result = if params[:verb] == "unfollow" follow = current_user.stop_following(followable) Notification.send_new_follower_notification_without_delay(follow, true) diff --git a/app/controllers/reactions_controller.rb b/app/controllers/reactions_controller.rb index e42f56f2e..9b3026706 100644 --- a/app/controllers/reactions_controller.rb +++ b/app/controllers/reactions_controller.rb @@ -4,6 +4,7 @@ class ReactionsController < ApplicationController def index skip_authorization + add_param_context(:article_id) if params[:article_id] id = params[:article_id] reactions = if efficient_current_user_id.present? @@ -21,6 +22,7 @@ class ReactionsController < ApplicationController reactions: reactions }.to_json else + add_param_context(:commentable_id, :commentable_type) comments = Comment.where( commentable_id: params[:commentable_id], commentable_type: params[:commentable_type], @@ -40,6 +42,7 @@ class ReactionsController < ApplicationController def create authorize Reaction + add_param_context(:reactable_id, :reactable_type, :category) Rails.cache.delete "count_for_reactable-#{params[:reactable_type]}-#{params[:reactable_id]}" category = params[:category] || "like" reaction = Reaction.where( diff --git a/app/controllers/stories_controller.rb b/app/controllers/stories_controller.rb index e73d77e9a..3510d1c1b 100644 --- a/app/controllers/stories_controller.rb +++ b/app/controllers/stories_controller.rb @@ -3,6 +3,7 @@ class StoriesController < ApplicationController before_action :set_cache_control_headers, only: %i[index search show] def index + add_param_context(:username, :tag) return handle_user_or_organization_or_podcast_index if params[:username] return handle_tag_index if params[:tag] handle_base_index @@ -19,6 +20,7 @@ class StoriesController < ApplicationController def show @story_show = true + add_param_context(:username, :slug) if @article = Article.find_by_path("/#{params[:username].downcase}/#{params[:slug]}")&.decorate handle_article_show elsif @article = Article.find_by_slug(params[:slug])&.decorate @@ -80,6 +82,7 @@ class StoriesController < ApplicationController @tag = params[:tag].downcase @page = (params[:page] || 1).to_i @tag_model = Tag.find_by_name(@tag) || not_found + add_param_context(:tag, :page) if @tag_model.alias_for.present? redirect_to "/t/#{@tag_model.alias_for}" return @@ -106,6 +109,7 @@ class StoriesController < ApplicationController @page = (params[:page] || 1).to_i num_articles = 15 @stories = article_finder(num_articles) + add_param_context(:page, :timeframe) if ["week", "month", "year", "infinity"].include?(params[:timeframe]) @stories = @stories.where("published_at > ?", Timeframer.new(params[:timeframe]).datetime). diff --git a/app/controllers/users_controller.rb b/app/controllers/users_controller.rb index 6d4153046..f980dd4ca 100644 --- a/app/controllers/users_controller.rb +++ b/app/controllers/users_controller.rb @@ -23,7 +23,7 @@ class UsersController < ApplicationController authorize @user # raise permitted_attributes(@user).to_s if @user.update(permitted_attributes(@user)) - RssReader.new.delay.fetch_user(@user) if @user.feed_url.present? + RssReader.new(request.request_id).delay.fetch_user(@user) if @user.feed_url.present? notice = "Your profile was successfully updated." if @user.export_requested? diff --git a/app/labor/rss_reader.rb b/app/labor/rss_reader.rb index 56258155b..09170e8e5 100644 --- a/app/labor/rss_reader.rb +++ b/app/labor/rss_reader.rb @@ -2,12 +2,17 @@ require "rss" require "open-uri" require "nokogiri" require "httparty" +require "securerandom" class RssReader def self.get_all_articles new.get_all_articles end + def initialize(request_id = nil) + @request_id = request_id + end + def get_all_articles User.where.not(feed_url: nil).each do |u| feed_url = u.feed_url.strip @@ -17,6 +22,8 @@ class RssReader end def fetch_user(user) + Thread.current[:request_id] = @request_id + Thread.current[:span_id] = @request_id create_articles_for_user(user) end @@ -29,22 +36,25 @@ class RssReader private def create_articles_for_user(user) - feed = fetch_rss(user.feed_url) - feed.entries.reverse_each do |item| - make_from_rss_item(item, user, feed) + with_span("create_articles_for_user", user_id: user.id, username: user.username) do |metadata| + feed = fetch_rss(user.feed_url) + 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) + end rescue StandardError => e - log_error("RssReaderError: occurred while creating article for " \ - "USER: #{user.username} " \ - "FEED-URL: #{user.feed_url} " \ - "ITEM-TITLE: #{item.title || 'no title'} " \ - "ERROR: #{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) 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}") end def get_item_count_error(feed) @@ -56,44 +66,59 @@ class RssReader end def fetch_rss(url) - xml = HTTParty.get(url).body - Feedjira::Feed.parse xml + with_span("fetch_rss", url: url) do |metadata| + xml = with_timer("http_get", metadata) do + HTTParty.get(url).body + end + with_timer("parse_xml", metadata) do + Feedjira::Feed.parse xml + end + end end def make_from_rss_item(item, user, feed) - return if medium_reply?(item) || article_exist?(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), - organization_id: user.organization_id.present? ? user.organization_id : nil - } - article = Article.create!(article_params) - return unless Rails.env.production? - SlackBot.delay.ping( - "New Article Retrieved via RSS: #{article.title}\nhttps://dev.to#{article.path}", - channel: Rails.env.production? ? "activity" : "test", - username: "article_bot", - icon_emoji: ":robot_face:", - ) + 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) + 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), + organization_id: user.organization_id.present? ? user.organization_id : nil + } + article = with_timer("save_article", metadata) do + Article.create!(article_params) + 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:", + ) + end end def assemble_body_markdown(item, user, feed, feed_source_url) - body = <<~HEREDOC - --- - title: #{item.title.strip} - published: false - tags: #{get_tags(item[:categories])} - canonical_url: #{user.feed_mark_canonical ? feed_source_url : ''} - --- + with_span("assemble_body_markdown", item_title: item.title) do + body = <<~HEREDOC + --- + title: #{item.title.strip} + published: false + tags: #{get_tags(item[:categories])} + canonical_url: #{user.feed_mark_canonical ? feed_source_url : ''} + --- - #{finalize_reverse_markdown(item, feed)} + #{finalize_reverse_markdown(item, feed)} - HEREDOC - body.strip + HEREDOC + body.strip + end end def get_tags(categories) @@ -112,16 +137,18 @@ class RssReader end def thorough_parsing(content, feed_url) - html_doc = Nokogiri::HTML(content) - find_and_replace_possible_links!(html_doc) - if feed_url.include?("medium.com") - parse_and_translate_gist_iframe!(html_doc) - parse_and_translate_youtube_iframe!(html_doc) - parse_and_translate_tweet!(html_doc) - else - clean_relative_path!(html_doc, feed_url) + with_span("thorough_parsing", content_length: content.length) do + html_doc = Nokogiri::HTML(content) + find_and_replace_possible_links!(html_doc) + if feed_url.include?("medium.com") + parse_and_translate_gist_iframe!(html_doc) + parse_and_translate_youtube_iframe!(html_doc) + parse_and_translate_tweet!(html_doc) + else + clean_relative_path!(html_doc, feed_url) + end + html_doc.to_html end - html_doc.to_html end def parse_and_translate_gist_iframe!(html_doc) @@ -210,8 +237,73 @@ class RssReader user.articles.find_by_title(item.title.strip.gsub('"', '\"')) end - def log_error(error_output) + def log_error(error_msg, metadata) logger = Logger.new(STDOUT) - logger.info(error_output) + parts = metadata.map { |k, v| [k.upcase.to_s.sub(/_/, "-"), v].join(": ") } + parts = parts.unshift(error_msg) + logger.info(parts.join(" ")) + + ev = $libhoney.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.span_id", SecureRandom.uuid) + ev.send + end + + # 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. + # + # The special sauce in this method is the definition / resetting of thread + # local variables in order to correctly propagate "parent" identifiers down + # into the block. + def with_span(name, metadata = nil) + trace_id = Thread.current[:request_id] + return yield({}) unless trace_id + + id = SecureRandom.uuid + start = Time.new + data = { + name: name, + "trace.span_id": id, + "trace.trace_id": trace_id, + service_name: "rss_reader" + } + # Capture the calling scope's span ID, then restore it at the end of the + # method. + parent_id = Thread.current[:span_id] + if parent_id + data["trace.parent_id"] = parent_id + end + + # 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 + ret = yield data + + data[:duration_ms] = (Time.new - start) * 1000 + if metadata + data.merge!(metadata) + end + + ev = $libhoney.event + ev.timestamp = start + ev.add(data) + ev.send + + ret + ensure + Thread.current[:span_id] = parent_id + end + + def with_timer(name, data) + start = Time.new + ret = yield + data[name + "_dur_ms"] = (Time.new - start) * 1000 if data + + ret end end diff --git a/config/initializers/honeycomb.rb b/config/initializers/honeycomb.rb new file mode 100644 index 000000000..2951e1276 --- /dev/null +++ b/config/initializers/honeycomb.rb @@ -0,0 +1,21 @@ +require 'libhoney' + +key = ApplicationConfig["HONEYCOMB_API_KEY"] +dataset = "dev.to-#{Rails.env}" + +if Rails.env.development? || Rails.env.test? + $libhoney = Libhoney::NullClient.new +else + $libhoney = 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 = $libhoney +end diff --git a/lib/instrumentation.rb b/lib/instrumentation.rb new file mode 100644 index 000000000..6d951c324 --- /dev/null +++ b/lib/instrumentation.rb @@ -0,0 +1,20 @@ +module Instrumentation + def add_param_context(*keys) + keys.each do |key| + honeycomb_metadata[key] = params[key] + end + end + + def add_context(metadata) + metadata.each do |key, value| + honeycomb_metadata[key] = value + end + end + + def append_to_honeycomb(request, controller_name) + 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 + end +end