diff --git a/app/controllers/publics_controller.rb b/app/controllers/publics_controller.rb index 3609bdefa..af9d57f9c 100644 --- a/app/controllers/publics_controller.rb +++ b/app/controllers/publics_controller.rb @@ -39,7 +39,7 @@ class PublicsController < ApplicationController return end - FEDERATION_LOGGER.info("webfinger profile request for :#{@person.id}") + logger.info "webfinger profile request for: #{@person.id}" render 'webfinger', :content_type => 'application/xrd+xml' end @@ -48,7 +48,7 @@ class PublicsController < ApplicationController end def receive_public - FEDERATION_LOGGER.info("recieved a public message") + logger.info "received a public message" Workers::ReceiveUnencryptedSalmon.perform_async(CGI::unescape(params[:xml])) render :nothing => true, :status => :ok end @@ -57,14 +57,14 @@ class PublicsController < ApplicationController person = Person.find_by_guid(params[:guid]) if person.nil? || person.owner_id.nil? - Rails.logger.error("Received post for nonexistent person #{params[:guid]}") + logger.error "Received post for nonexistent person #{params[:guid]}" render :nothing => true, :status => 404 return end @user = person.owner - FEDERATION_LOGGER.info("recieved a private message for user:#{@user.id}") + logger.info "received a private message for user: #{@user.id}" Workers::ReceiveEncryptedSalmon.perform_async(@user.id, CGI::unescape(params[:xml])) render :nothing => true, :status => 202 diff --git a/app/mailers/notification_mailers/base.rb b/app/mailers/notification_mailers/base.rb index b3cc8136a..efbde43a1 100644 --- a/app/mailers/notification_mailers/base.rb +++ b/app/mailers/notification_mailers/base.rb @@ -1,5 +1,7 @@ module NotificationMailers class Base + include Diaspora::Logging + attr_accessor :recipient, :sender delegate :unconfirmed_email, :confirm_email_token, @@ -53,9 +55,5 @@ module NotificationMailers logger.info(log_string) end - - def logger - @logger ||= ::Logging::Logger[self] - end end end diff --git a/app/models/user.rb b/app/models/user.rb index 364a33350..8de37ecaf 100644 --- a/app/models/user.rb +++ b/app/models/user.rb @@ -232,7 +232,7 @@ class User < ActiveRecord::Base end def dispatch_post(post, opts={}) - FEDERATION_LOGGER.info("user:#{self.id} dispatching #{post.class}:#{post.guid}") + logger.info "user:#{id} dispatching #{post.class}:#{post.guid}" Postzord::Dispatcher.defer_build_and_post(self, post, opts) end diff --git a/app/workers/base.rb b/app/workers/base.rb index 2a614663e..d410a103d 100644 --- a/app/workers/base.rb +++ b/app/workers/base.rb @@ -8,6 +8,8 @@ module Workers sidekiq_options backtrace: (bt = AppConfig.environment.sidekiq.backtrace.get) && bt.to_i, retry: (rt = AppConfig.environment.sidekiq.retry.get) && rt.to_i + include Diaspora::Logging + # In the long term we need to eliminate the cause of these def suppress_annoying_errors(&block) yield @@ -19,19 +21,13 @@ module Workers # Friendica seems to provoke Diaspora::NonPublic, Diaspora::XMLNotParseable => e - Rails.logger.info("error on receive: #{e.class}") + logger.warn "error on receive: #{e.class}" rescue ActiveRecord::RecordInvalid => e - Rails.logger.info("failed to save received object: #{e.record.errors.full_messages}") + logger.warn "failed to save received object: #{e.record.errors.full_messages}" raise e unless %w( "already been taken" "is ignored by the post author" ).any? {|reason| e.message.include? reason } end - - private - - def logger - @logger ||= ::Logging::Logger[self] - end end end diff --git a/app/workers/http_multi.rb b/app/workers/http_multi.rb index e370cd981..dfc1b9591 100644 --- a/app/workers/http_multi.rb +++ b/app/workers/http_multi.rb @@ -31,7 +31,7 @@ module Workers if retry_count < MAX_RETRIES Workers::HttpMulti.perform_in(1.hour, user_id, encoded_object_xml, hydra.people_to_retry, dispatcher_class_as_string, retry_count + 1) else - Rails.logger.info("event=http_multi_abandon sender_id=#{user_id} failed_recipient_ids='[#{person_ids.join(', ')}] '") + logger.info "event=http_multi_abandon sender_id=#{user_id} failed_recipient_ids='[#{person_ids.join(', ')}]'" end end end diff --git a/app/workers/receive_unencrypted_salmon.rb b/app/workers/receive_unencrypted_salmon.rb index 2f7085730..4340443bc 100644 --- a/app/workers/receive_unencrypted_salmon.rb +++ b/app/workers/receive_unencrypted_salmon.rb @@ -8,13 +8,8 @@ module Workers def perform(xml) suppress_annoying_errors do - begin - receiver = Postzord::Receiver::Public.new(xml) - receiver.perform! - rescue => e - FEDERATION_LOGGER.info(e.message) - raise e - end + receiver = Postzord::Receiver::Public.new(xml) + receiver.perform! end end end diff --git a/config/initializers/load_libraries.rb b/config/initializers/load_libraries.rb index cd3ee6065..ff4f78492 100644 --- a/config/initializers/load_libraries.rb +++ b/config/initializers/load_libraries.rb @@ -14,7 +14,6 @@ require 'diaspora' require 'direction_detector' require 'email_inviter' require 'evil_query' -require 'federation_logger' require 'h_card' require 'hydra_wrapper' require 'postzord' diff --git a/lib/diaspora/fetcher/public.rb b/lib/diaspora/fetcher/public.rb index cb920b243..acc0e6479 100644 --- a/lib/diaspora/fetcher/public.rb +++ b/lib/diaspora/fetcher/public.rb @@ -2,6 +2,7 @@ # licensed under the Affero General Public License version 3 or later. See # the COPYRIGHT file. module Diaspora; module Fetcher; class Public + include Diaspora::Logging # various states that can be assigned to a person to describe where # in the process of fetching their public posts we're currently at @@ -60,14 +61,14 @@ module Diaspora; module Fetcher; class Public begin retrieve_posts rescue => e - FEDERATION_LOGGER.error "unable to retrieve public posts for #{@person.diaspora_handle}" + logger.error "unable to retrieve public posts for #{@person.diaspora_handle}" raise e end begin process_posts rescue => e - FEDERATION_LOGGER.error "unable to process public posts for #{@person.diaspora_handle}" + logger.error "unable to process public posts for #{@person.diaspora_handle}" raise e end end @@ -77,14 +78,14 @@ module Diaspora; module Fetcher; class Public def retrieve_posts set_fetch_status Public::Status_Running - FEDERATION_LOGGER.info "fetching public posts for #{@person.diaspora_handle}" + logger.info "fetching public posts for #{@person.diaspora_handle}" resp = Faraday.get("#{@person.url}people/#{@person.guid}/stream") do |req| req.headers['Accept'] = 'application/json' req.headers['User-Agent'] = 'diaspora-fetcher' end - FEDERATION_LOGGER.debug resp.body.to_s[0..250] + logger.debug "fetched response: #{resp.body.to_s[0..250]}" @data = JSON.parse resp.body set_fetch_status Public::Status_Fetched @@ -97,9 +98,9 @@ module Diaspora; module Fetcher; class Public @data.each do |post| next unless validate(post) - FEDERATION_LOGGER.info "saving fetched post (#{post['guid']}) to database" + logger.info "saving fetched post (#{post['guid']}) to database" - FEDERATION_LOGGER.debug post.to_s[0..250] + logger.debug "post: #{post.to_s[0..250]}" # disable some stuff we don't want for bulk inserts StatusMessage.skip_callback :create, :set_guid @@ -147,7 +148,7 @@ module Diaspora; module Fetcher; class Public def check_existing post new_post = (Post.find_by_guid(post['guid']).blank?) - FEDERATION_LOGGER.warn "a post with that guid (#{post['guid']}) already exists" unless new_post + logger.warn "a post with that guid (#{post['guid']}) already exists" unless new_post new_post end @@ -158,7 +159,7 @@ module Diaspora; module Fetcher; class Public guid = post['author']['guid'] equal = (guid == @person.guid) - FEDERATION_LOGGER.warn "the author (#{guid}) does not match the person currently being processed (#{@person.guid})" unless equal + logger.warn "the author (#{guid}) does not match the person currently being processed (#{@person.guid})" unless equal equal end @@ -167,7 +168,7 @@ module Diaspora; module Fetcher; class Public def check_public post ispublic = (post['public'] == true) - FEDERATION_LOGGER.warn "the post (#{post['guid']}) is not public, this is not intended..." unless ispublic + logger.warn "the post (#{post['guid']}) is not public, this is not intended..." unless ispublic ispublic end @@ -176,7 +177,7 @@ module Diaspora; module Fetcher; class Public def check_type post type_ok = (post['post_type'] == "StatusMessage") - FEDERATION_LOGGER.warn "the post (#{post['guid']}) has a type, which cannot be handled (#{post['post_type']})" unless type_ok + logger.warn "the post (#{post['guid']}) has a type, which cannot be handled (#{post['post_type']})" unless type_ok type_ok end diff --git a/lib/diaspora/logging.rb b/lib/diaspora/logging.rb new file mode 100644 index 000000000..4fe8c04ac --- /dev/null +++ b/lib/diaspora/logging.rb @@ -0,0 +1,10 @@ +# a logging mixin providing the logger +module Diaspora + module Logging + private + + def logger + @logger ||= ::Logging::Logger[self] + end + end +end diff --git a/lib/federated/generator.rb b/lib/federated/generator.rb index ab6025ef2..4ee81511a 100644 --- a/lib/federated/generator.rb +++ b/lib/federated/generator.rb @@ -1,5 +1,7 @@ module Federated class Generator + include Diaspora::Logging + def initialize(user, target) @user = user @target = target @@ -8,7 +10,7 @@ module Federated def create!(options={}) relayable = build(options) if relayable.save! - FEDERATION_LOGGER.info("user:#{@user.id} dispatching #{relayable.class}:#{relayable.guid}") + logger.info "user:#{@user.id} dispatching #{relayable.class}:#{relayable.guid}" Postzord::Dispatcher.defer_build_and_post(@user, relayable) relayable end @@ -28,4 +30,4 @@ module Federated {} end end -end \ No newline at end of file +end diff --git a/lib/federation_logger.rb b/lib/federation_logger.rb deleted file mode 100644 index aa6097d15..000000000 --- a/lib/federation_logger.rb +++ /dev/null @@ -1,118 +0,0 @@ -#custom_logger.rb - -class ActiveSupport::BufferedLogger - def formatter=(formatter) - @log.formatter = formatter - end -end - -class Formatter - COLORS = { - 'FG' => { - 'black' => '30', - 'red' => '31', - 'green' => '32', - 'yellow' => '33', - 'blue' => '34', - 'violet' => '35', - 'cyan' => '36', - 'white' => '37', - }, - 'BG' => { - 'black' => '40', - 'red' => '41', - 'green' => '42', - 'yellow' => '43', - 'blue' => '44', - 'violet' => '45', - 'cyan' => '46', - 'white' => '47', - } - } - - DULL = '0' - BRIGHT = '1' - NULL = '00' - - ESC = "\e" - RESET = "#{ESC}[00;0;00m" - # example: \033[40;0;37m white text on black background - - SEVERITY_TO_TAG_MAP = {'DEBUG'=>'meh', 'INFO'=>'fyi', 'WARN'=>'hmm', 'ERROR'=>'wtf', 'FATAL'=>'omg', 'UNKNOWN'=>'???'} - SEVERITY_TO_COLOR_MAP = {'DEBUG'=>'white', 'INFO'=>'green', 'WARN'=>'yellow', 'ERROR'=>'red', 'FATAL'=>'red', 'UNKNOWN'=>'white'} - - def initialize - @colors_enabled = true - end - - def random - @random ||= COLORS['FG'].keys[3] - end - - def colors? - @colors_enabled - end - - def fg name - COLORS['FG'][name] - end - - def bg name - COLORS['BG'][name] - end - - def colorize(message, c_fg='white', c_bg='black', strong=0) - if colors? - "#{ESC}[#{fg(c_fg)};#{bg(c_bg)};#{strong==0 ? DULL : BRIGHT}m#{message}#{RESET}" - else - message - end - end - - def call(severity, time, progname, msg) - fmt_prefix = pretty_prefix(severity, time) - fmt_msg = pretty_message(msg) - - "#{fmt_prefix} #{fmt_msg}\n" - end - - def pretty_prefix(severity, time) - color = SEVERITY_TO_COLOR_MAP[severity] - fmt_severity = colorize(sprintf("%-3s","#{SEVERITY_TO_TAG_MAP[severity]}"), color, 'black', 1) - fmt_time = colorize(time.strftime("%s.%L")) - fmt_env = colorize(Rails.env, random, 'black', 1) - - "#{fmt_env} - #{fmt_time} [#{fmt_severity}] (pid:#{$$})" - end - - def pretty_message msg - w = 130 - txt_w = (w - Rails.env.size - 3) - - # get the prefix without colors, just for the length - @colors_enabled = false - prefix = pretty_prefix("DEBUG", Time.now).size + 1 - @colors_enabled = true # restore value - - if (msg.size <= (w-prefix)) - msg - else - output = msg.strip.scan(/.{1,#{txt_w}}/).flatten.map { |line| sprintf("%#{w}s", sprintf("%-#{txt_w}s", line)) }.join("\n") - "\n#{output}" - end - end - -end - -class FederationLogger < ActiveSupport::BufferedLogger -end - -if Rails.env.match(/integration/) - puts "using federation logger" - logfile = File.open(Rails.root.join("log", "federation_logger.log"), 'a') #create log file - logfile.sync = true #automatically flushes data to file - FEDERATION_LOGGER = FederationLogger.new(logfile) #constant accessible anywhere - FEDERATION_LOGGER.formatter = Formatter.new -else - FEDERATION_LOGGER = Rails.logger -end diff --git a/lib/postzord/receiver.rb b/lib/postzord/receiver.rb index f411de7c3..cb99c2bc2 100644 --- a/lib/postzord/receiver.rb +++ b/lib/postzord/receiver.rb @@ -4,6 +4,8 @@ class Postzord::Receiver + include Diaspora::Logging + require 'postzord/receiver/private' require 'postzord/receiver/public' require 'postzord/receiver/local_batch' @@ -14,7 +16,8 @@ class Postzord::Receiver def author_does_not_match_xml_author? if (@author.diaspora_handle != xml_author) - FEDERATION_LOGGER.info("event=receive status=abort reason='author in xml does not match retrieved person' payload_type=#{@object.class} sender=#{@author.diaspora_handle}") + logger.info "event=receive status=abort reason='author in xml does not match retrieved person' " \ + "payload_type=#{@object.class} sender=#{@author.diaspora_handle}" return true end end diff --git a/lib/postzord/receiver/local_batch.rb b/lib/postzord/receiver/local_batch.rb index 454121f6f..e45936d36 100644 --- a/lib/postzord/receiver/local_batch.rb +++ b/lib/postzord/receiver/local_batch.rb @@ -14,7 +14,7 @@ class Postzord::Receiver::LocalBatch < Postzord::Receiver end def receive! - FEDERATION_LOGGER.info("receiving local batch for #{@object.inspect}") + logger.info "receiving local batch for #{@object.inspect}" if @object.respond_to?(:relayable?) receive_relayable else @@ -25,7 +25,7 @@ class Postzord::Receiver::LocalBatch < Postzord::Receiver # 09/27/11 this is slow notify_users - FEDERATION_LOGGER.info("receiving local batch completed for #{@object.inspect}") + logger.info "receiving local batch completed for #{@object.inspect}" true end diff --git a/lib/postzord/receiver/private.rb b/lib/postzord/receiver/private.rb index 0a45f9744..224eacf78 100644 --- a/lib/postzord/receiver/private.rb +++ b/lib/postzord/receiver/private.rb @@ -19,36 +19,32 @@ class Postzord::Receiver::Private < Postzord::Receiver if @sender && self.salmon.verified_for_key?(@sender.public_key) parse_and_receive(salmon.parsed_data) else - FEDERATION_LOGGER.info("event=receive status=abort recipient=#{@user.diaspora_handle} sender=#{@salmon.author_id} reason='not_verified for key'") + logger.error "event=receive status=abort reason='not_verified for key' " \ + "recipient=#{@user.diaspora_handle} sender=#{@salmon.author_id}" false end rescue => e - #this sucks - FEDERATION_LOGGER.error("Failure to receive #{@object.class} from sender:#{@sender.id} for user:#{@user.id}: #{e.message}\n#{@object.inspect}") + logger.error "failed to receive #{@object.class} from sender:#{@sender.id} for user:#{@user.id}: #{e.message}\n" \ + "#{@object.inspect}" raise e end def parse_and_receive(xml) @object ||= Diaspora::Parser.from_xml(xml) - return if @object.nil? + return if @object.nil? - FEDERATION_LOGGER.info("user:#{@user.id} starting private receive from person:#{@sender.guid}") + logger.info "user:#{@user.id} starting private receive from person:#{@sender.guid}" - if self.validate_object - set_author! - receive_object - FEDERATION_LOGGER.info("object received: [#{@object.class}#{@object.respond_to?(:text) ? ":'#{@object.text}'" : ''}]") - else - FEDERATION_LOGGER.error("failed to receive object from #{@object.author}: #{@object.inspect}") - raise "not a valid object:#{@object.inspect}" - end + validate_object + set_author! + receive_object end # @return [Object] def receive_object obj = @object.receive(@user, @author) Notification.notify(@user, obj, @author) if obj.respond_to?(:notification_type) - FEDERATION_LOGGER.info("user:#{@user.id} successfully received private post from person #{@sender.guid}: #{@object.inspect}") + logger.info "user:#{@user.id} successfully received #{@object.class} from person #{@sender.guid}: #{@object.inspect}" obj end @@ -91,14 +87,16 @@ class Postzord::Receiver::Private < Postzord::Receiver #validations def relayable_without_parent? if @object.respond_to?(:relayable?) && @object.parent.nil? - FEDERATION_LOGGER.error("event=receive status=abort reason='received a comment but no corresponding post' recipient=#{@user_person.diaspora_handle} sender=#{@sender.diaspora_handle} payload_type=#{@object.class})") + logger.error "event=receive status=abort reason='no corresponding post' type=#{@object.class} " \ + "recipient=#{@user_person.diaspora_handle} sender=#{@sender.diaspora_handle}" return true end end def contact_required_unless_request unless @object.is_a?(Request) || @user.contact_for(@sender) - FEDERATION_LOGGER.error("event=receive status=abort reason='sender not connected to recipient' recipient=#{@user_person.diaspora_handle} sender=#{@sender.diaspora_handle}") + logger.error "event=receive status=abort reason='sender not connected to recipient' type=#{@object.class} " \ + "recipient=#{@user_person.diaspora_handle} sender=#{@sender.diaspora_handle}" return true end end diff --git a/lib/postzord/receiver/public.rb b/lib/postzord/receiver/public.rb index 8c5d51d1f..002019ae6 100644 --- a/lib/postzord/receiver/public.rb +++ b/lib/postzord/receiver/public.rb @@ -10,7 +10,7 @@ class Postzord::Receiver::Public < Postzord::Receiver @salmon = Salmon::Slap.from_xml(xml) @author = Webfinger.new(@salmon.author_id).fetch - FEDERATION_LOGGER.info("Receiving public object from person:#{@author.id}") + logger.info "Receiving public object from person:#{@author.id}" end # @return [Boolean] @@ -25,7 +25,7 @@ class Postzord::Receiver::Public < Postzord::Receiver return false unless save_object - FEDERATION_LOGGER.info("received a #{@object.inspect}") + logger.info "received a #{@object.inspect}" if @object.is_a?(SignedRetraction) # feels like a hack self.recipient_user_ids.each do |user_id| user = User.where(id: user_id).first diff --git a/lib/webfinger.rb b/lib/webfinger.rb index 385c2b40b..5c28a4e90 100644 --- a/lib/webfinger.rb +++ b/lib/webfinger.rb @@ -3,6 +3,8 @@ # the COPYRIGHT file. class Webfinger + include Diaspora::Logging + attr_accessor :host_meta_xrd, :webfinger_profile_xrd, :webfinger_profile, :hcard, :hcard_xrd, :person, :account, :ssl @@ -28,7 +30,7 @@ class Webfinger end def get(url) - Rails.logger.info("Getting: #{url} for #{account}") + logger.info "Getting: #{url} for #{account}" begin res = Faraday.get(url) unless res.success? @@ -36,10 +38,10 @@ class Webfinger end res.body rescue OpenSSL::SSL::SSLError => e - Rails.logger.info "Failed to fetch #{url}: SSL setup invalid" + logger.error "Failed to fetch #{url}: SSL setup invalid" raise e rescue => e - Rails.logger.info("Failed to fetch: #{url} for #{account}; #{e.message}") + logger.error "Failed to fetch: #{url} for #{account}; #{e.message}" raise e end end @@ -53,13 +55,13 @@ class Webfinger end def create_or_update_person_from_webfinger_profile! - FEDERATION_LOGGER.info("webfingering #{account}, it is not known or needs updating") + logger.info "webfingering #{account}, it is not known or needs updating" if person #update my profile please person.assign_new_profile_from_hcard(self.hcard) else person = make_person_from_webfinger end - FEDERATION_LOGGER.info("successfully webfingered #{@account}") if person + logger.info "successfully webfingered #{@account}" if person person end @@ -98,7 +100,7 @@ class Webfinger def webfinger_profile_xrd @webfinger_profile_xrd ||= get(webfinger_profile_url) - FEDERATION_LOGGER.warn "#{@account} doesn't exists anymore" if @webfinger_profile_xrd == false + logger.warn "#{@account} doesn't exists anymore" if @webfinger_profile_xrd == false @webfinger_profile_xrd end