From ab727fc846af974988db8a9c34c7319337219435 Mon Sep 17 00:00:00 2001 From: Maxwell Salzberg Date: Tue, 14 Feb 2012 15:13:45 -0800 Subject: [PATCH 1/2] federation logger now in place. --- app/controllers/publics_controller.rb | 4 ++ app/controllers/status_messages_controller.rb | 6 +-- app/models/jobs/base.rb | 7 +--- app/models/jobs/receive_unencrypted_salmon.rb | 9 ++++- app/models/user.rb | 1 + config/environment.rb | 1 + config/environments/integration1.rb | 39 +++++++++++++++++++ .../{integration_2.rb => integration2.rb} | 1 + config/environments/integration_1.rb | 5 ++- lib/federated/generator.rb | 1 + lib/federation_logger.rb | 15 +++++++ lib/postzord/receiver/local_batch.rb | 3 ++ lib/postzord/receiver/private.rb | 28 ++++++++----- lib/postzord/receiver/public.rb | 10 +++-- lib/webfinger.rb | 4 +- 15 files changed, 107 insertions(+), 27 deletions(-) create mode 100644 config/environments/integration1.rb rename config/environments/{integration_2.rb => integration2.rb} (99%) create mode 100644 lib/federation_logger.rb diff --git a/app/controllers/publics_controller.rb b/app/controllers/publics_controller.rb index 80f1107ec..3906d3f30 100644 --- a/app/controllers/publics_controller.rb +++ b/app/controllers/publics_controller.rb @@ -50,6 +50,7 @@ class PublicsController < ApplicationController return end + FEDERATION_LOGGER.info("webfinger profile request for :#{@person.id}") render 'webfinger', :content_type => 'application/xrd+xml' end @@ -58,6 +59,7 @@ class PublicsController < ApplicationController end def receive_public + FEDERATION_LOGGER.info("recieved a public message") Resque.enqueue(Jobs::ReceiveUnencryptedSalmon, CGI::unescape(params[:xml])) render :nothing => true, :status => :ok end @@ -72,6 +74,8 @@ class PublicsController < ApplicationController end @user = person.owner + + FEDERATION_LOGGER.info("recieved a private message for user:#{@user.id}") Resque.enqueue(Jobs::ReceiveEncryptedSalmon, @user.id, CGI::unescape(params[:xml])) render :nothing => true, :status => 202 diff --git a/app/controllers/status_messages_controller.rb b/app/controllers/status_messages_controller.rb index 8553fb079..361636c9d 100644 --- a/app/controllers/status_messages_controller.rb +++ b/app/controllers/status_messages_controller.rb @@ -54,9 +54,9 @@ class StatusMessagesController < ApplicationController current_user.dispatch_post(@status_message, :url => short_post_url(@status_message.guid), :service_types => receiving_services) - @status_message.photos.each do |photo| - current_user.dispatch_post(photo) - end + # @status_message.photos.each do |photo| + # current_user.dispatch_post(photo) + # end current_user.participate!(@status_message) diff --git a/app/models/jobs/base.rb b/app/models/jobs/base.rb index bf576d523..69b9ea856 100644 --- a/app/models/jobs/base.rb +++ b/app/models/jobs/base.rb @@ -15,11 +15,8 @@ module Jobs begin yield rescue Exception => e - if DUMB_ERROR_MESSAGES.include?(e.message) - Rails.logger.error(e.message) - else - raise e - end + FEDERATION_LOGGER.info(e.message) + raise e end end end diff --git a/app/models/jobs/receive_unencrypted_salmon.rb b/app/models/jobs/receive_unencrypted_salmon.rb index 1fd8f714d..084a27e20 100644 --- a/app/models/jobs/receive_unencrypted_salmon.rb +++ b/app/models/jobs/receive_unencrypted_salmon.rb @@ -9,8 +9,13 @@ module Jobs @queue = :receive def self.perform(xml) - receiver = Postzord::Receiver::Public.new(xml) - receiver.perform! + begin + receiver = Postzord::Receiver::Public.new(xml) + receiver.perform! + rescue Exception => e + FEDERATION_LOGGER.info(e.message) + raise e + end end end end diff --git a/app/models/user.rb b/app/models/user.rb index 2562e38b6..e35314d50 100644 --- a/app/models/user.rb +++ b/app/models/user.rb @@ -274,6 +274,7 @@ class User < ActiveRecord::Base end def dispatch_post(post, opts={}) + FEDERATION_LOGGER.info("user:#{self.id} dispatching #{post.class}:#{post.guid}") Postzord::Dispatcher.defer_build_and_post(self, post, opts) end diff --git a/config/environment.rb b/config/environment.rb index 98eae5c26..94af3cec7 100644 --- a/config/environment.rb +++ b/config/environment.rb @@ -37,6 +37,7 @@ USERNAME_BLACKLIST = ['admin', 'administrator', 'hostmaster', 'info', 'postmaste # Initialize the rails application Diaspora::Application.initialize! +require File.join(Rails.root, 'lib/federation_logger') # allow token auth only for posting activitystream photos module Devise diff --git a/config/environments/integration1.rb b/config/environments/integration1.rb new file mode 100644 index 000000000..a3a5ee606 --- /dev/null +++ b/config/environments/integration1.rb @@ -0,0 +1,39 @@ +# Copyright (c) 2010-2011, Diaspora Inc. This file is +# licensed under the Affero General Public License version 3 or later. See +# the COPYRIGHT file. + +Diaspora::Application.configure do + # Settings specified here will take precedence over those in config/environment.rb + + # In the development environment your application's code is reloaded on + # every request. This slows down response time but is perfect for development + # since you don't have to restart the webserver when you make code changes. + config.cache_classes = false + + # Log error messages when you accidentally call methods on nil. + config.whiny_nils = true + + # Show full error reports and disable caching + config.consider_all_requests_local = true + config.action_controller.perform_caching = false + + # Don't care if the mailer can't send + config.action_mailer.raise_delivery_errors = false + config.active_support.deprecation = :log + + config.threadsafe! + + # Monkeypatch around the nasty "2.5MB exception page" issue, caused by very large environment vars + # This snippet via: http://stackoverflow.com/questions/3114993/exception-pages-in-development-mode-take-upwards-of-15-30-seconds-to-render-why + # Relevant Rails ticket: https://rails.lighthouseapp.com/projects/8994/tickets/5027-_request_and_responseerb-and-diagnosticserb-take-an-increasingly-long-time-to-render-in-development-with-multiple-show-tables-calls + config.after_initialize do + module SmallInspect + def inspect + "<#{self.class.name} - tooooo long>" + end + end + [ActionController::Base, ActionDispatch::RemoteIp::RemoteIpGetter, OmniAuth::Strategy, Warden::Proxy].each do |klazz| + klazz.send(:include, SmallInspect) + end + end +end diff --git a/config/environments/integration_2.rb b/config/environments/integration2.rb similarity index 99% rename from config/environments/integration_2.rb rename to config/environments/integration2.rb index f7a6974e2..d5630d80d 100644 --- a/config/environments/integration_2.rb +++ b/config/environments/integration2.rb @@ -21,6 +21,7 @@ Diaspora::Application.configure do # Don't care if the mailer can't send config.action_mailer.raise_delivery_errors = false config.active_support.deprecation = :log + #config.threadsafe! # Monkeypatch around the nasty "2.5MB exception page" issue, caused by very large environment vars diff --git a/config/environments/integration_1.rb b/config/environments/integration_1.rb index 443bf1737..042a23caa 100644 --- a/config/environments/integration_1.rb +++ b/config/environments/integration_1.rb @@ -1,4 +1,4 @@ -# Copyright (c) 2010-2011, Diaspora Inc. This file is + # Copyright (c) 2010-2011, Diaspora Inc. This file is # licensed under the Affero General Public License version 3 or later. See # the COPYRIGHT file. @@ -8,7 +8,7 @@ Diaspora::Application.configure do # In the development environment your application's code is reloaded on # every request. This slows down response time but is perfect for development # since you don't have to restart the webserver when you make code changes. - config.cache_classes = true + config.cache_classes = false # Log error messages when you accidentally call methods on nil. config.whiny_nils = true @@ -20,6 +20,7 @@ Diaspora::Application.configure do # Don't care if the mailer can't send config.action_mailer.raise_delivery_errors = false config.active_support.deprecation = :log + config.threadsafe! # Monkeypatch around the nasty "2.5MB exception page" issue, caused by very large environment vars diff --git a/lib/federated/generator.rb b/lib/federated/generator.rb index 68f95e292..ba90546db 100644 --- a/lib/federated/generator.rb +++ b/lib/federated/generator.rb @@ -8,6 +8,7 @@ module Federated def create!(options={}) relayable = build(options) if relayable.save + FEDERATION_LOGGER.info("user:#{@user.id} dispatching #{relayable.class}:#{relayable.guid}") Postzord::Dispatcher.defer_build_and_post(@user, relayable) relayable else diff --git a/lib/federation_logger.rb b/lib/federation_logger.rb new file mode 100644 index 000000000..93dc430f0 --- /dev/null +++ b/lib/federation_logger.rb @@ -0,0 +1,15 @@ +#custom_logger.rb +class FederationLogger < Logger + def format_message(severity, timestamp, progname, msg) + "#{Rails.env}-#{timestamp}: #{msg}\n" + end +end + +if Rails.env.match(/integration/) + puts "using federation logger" + logfile = File.open(File.join(Rails.root, "/log/#{Rails.env}_federation.log"), 'a') #create log file + logfile.sync = true #automatically flushes data to file + FEDERATION_LOGGER = FederationLogger.new(logfile) #constant accessible anywhere +else + FEDERATION_LOGGER = Rails.logger +end \ No newline at end of file diff --git a/lib/postzord/receiver/local_batch.rb b/lib/postzord/receiver/local_batch.rb index 3da01378e..45f0af1c0 100644 --- a/lib/postzord/receiver/local_batch.rb +++ b/lib/postzord/receiver/local_batch.rb @@ -10,9 +10,11 @@ class Postzord::Receiver::LocalBatch < Postzord::Receiver @object = object @recipient_user_ids = recipient_user_ids @users = User.where(:id => @recipient_user_ids) + end def receive! + FEDERATION_LOGGER.info("receiving local batch for #{@object.class}:#{@object.guid}") if @object.respond_to?(:relayable?) receive_relayable else @@ -23,6 +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.class}:#{@object.guid}") true end diff --git a/lib/postzord/receiver/private.rb b/lib/postzord/receiver/private.rb index 5efe118f7..8b1851408 100644 --- a/lib/postzord/receiver/private.rb +++ b/lib/postzord/receiver/private.rb @@ -19,11 +19,17 @@ class Postzord::Receiver::Private < Postzord::Receiver end def receive! - if @sender && self.salmon.verified_for_key?(@sender.public_key) - parse_and_receive(salmon.parsed_data) - else - Rails.logger.info("event=receive status=abort recipient=#{@user.diaspora_handle} sender=#{@salmon.author_id} reason='not_verified for key'") - false + begin + 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'") + false + end + rescue Exception => e + #this sucks + FEDERATION_LOGGER.info("Failure to receive #{@object.class}:#{@object.id} for sender:#{@sender.id} for user:#{@user.id}: #{e.message}") + raise e end end @@ -31,12 +37,14 @@ class Postzord::Receiver::Private < Postzord::Receiver @object ||= Diaspora::Parser.from_xml(xml) return if @object.nil? - Rails.logger.info("event=receive status=start recipient=#{@user_person.diaspora_handle} payload_type=#{@object.class} sender=#{@sender.diaspora_handle}") + FEDERATION_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}") else + FEDERATION_LOGGER.info("failed to receive object from #{@object.author}: #{@object.inspect}") raise "not a valid object:#{@object.inspect}" end end @@ -45,7 +53,7 @@ class Postzord::Receiver::Private < Postzord::Receiver def receive_object obj = @object.receive(@user, @author) Notification.notify(@user, obj, @author) if obj.respond_to?(:notification_type) - Rails.logger.info("event=receive status=complete recipient=#{@user_person.diaspora_handle} sender=#{@sender.diaspora_handle} payload_type=#{obj.class}") + FEDERATION_LOGGER.info("user:#{@user.id} successfully received private post from person#{@sender.guid} #{@object.class}:#{@object.guid}") obj end @@ -87,21 +95,21 @@ class Postzord::Receiver::Private < Postzord::Receiver #validations def relayable_without_parent? if @object.respond_to?(:relayable?) && @object.parent.nil? - Rails.logger.info("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})") + FEDERATION_LOGGER.info("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})") return true end end def author_does_not_match_xml_author? if (@author.diaspora_handle != xml_author) - Rails.logger.info("event=receive status=abort reason='author in xml does not match retrieved person' payload_type=#{@object.class} recipient=#{@user_person.diaspora_handle} sender=#{@sender.diaspora_handle}") + FEDERATION_LOGGER.info("event=receive status=abort reason='author in xml does not match retrieved person' payload_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) - Rails.logger.info("event=receive status=abort reason='sender not connected to recipient' recipient=#{@user_person.diaspora_handle} sender=#{@sender.diaspora_handle}") + FEDERATION_LOGGER.info("event=receive status=abort reason='sender not connected to recipient' 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 e6bbf8ba3..2955def04 100644 --- a/lib/postzord/receiver/public.rb +++ b/lib/postzord/receiver/public.rb @@ -9,6 +9,8 @@ class Postzord::Receiver::Public < Postzord::Receiver def initialize(xml) @salmon = Salmon::Slap.from_xml(xml) @author = Webfinger.new(@salmon.author_id).fetch + + FEDERATION_LOGGER.info("Receving public post from person:#{@author.id}") end # @return [Boolean] @@ -18,14 +20,16 @@ class Postzord::Receiver::Public < Postzord::Receiver # @return [void] def receive! - return false unless verified_signature? - return false unless save_object + raise 'not valid signature' unless verified_signature? + raise 'unable to save object' unless save_object + FEDERATION_LOGGER.info("received a #{@object.class}:#{@object.guid} with author #{@object.author.diaspora_handle}") if @object.respond_to?(:relayable?) receive_relayable elsif @object.is_a?(AccountDeletion) #nothing else + FEDERATION_LOGGER.info("queuing local batchjob") Resque.enqueue(Jobs::ReceiveLocalBatch, @object.class.to_s, @object.id, self.recipient_user_ids) true end @@ -47,7 +51,7 @@ class Postzord::Receiver::Public < Postzord::Receiver def save_object @object = Diaspora::Parser::from_xml(@salmon.parsed_data) raise "Object is not public" if object_can_be_public_and_it_is_not? - @object.save if @object + @object.save! if @object end # @return [Array] User ids diff --git a/lib/webfinger.rb b/lib/webfinger.rb index 83c3df20d..6400789e6 100644 --- a/lib/webfinger.rb +++ b/lib/webfinger.rb @@ -9,7 +9,6 @@ class Webfinger def initialize(account) self.account = account self.ssl = true - Rails.logger.info("event=webfinger status=initialized target=#{account}") end @@ -46,12 +45,13 @@ class Webfinger end def create_or_update_person_from_webfinger_profile! + FEDERATION_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 - Rails.logger.info("event=webfinger status=success route=remote target=#{@account}") + FEDERATION_LOGGER.logger.info("successfully webfingered#{@account}") person end From 1f4e255f57ba4efbf30f780d5fd039762d91de34 Mon Sep 17 00:00:00 2001 From: Maxwell Salzberg Date: Fri, 17 Feb 2012 14:59:42 -0800 Subject: [PATCH 2/2] fix logging to work great with non-persisted objects --- app/models/jobs/base.rb | 6 +++-- config/environments/integration_1.rb | 39 ---------------------------- lib/postzord/receiver/local_batch.rb | 4 +-- lib/postzord/receiver/private.rb | 4 +-- lib/postzord/receiver/public.rb | 7 +++-- lib/webfinger.rb | 2 +- 6 files changed, 12 insertions(+), 50 deletions(-) delete mode 100644 config/environments/integration_1.rb diff --git a/app/models/jobs/base.rb b/app/models/jobs/base.rb index 69b9ea856..f947e7c0a 100644 --- a/app/models/jobs/base.rb +++ b/app/models/jobs/base.rb @@ -15,8 +15,10 @@ module Jobs begin yield rescue Exception => e - FEDERATION_LOGGER.info(e.message) - raise e + Rails.info("error in job: #{e.message}") + unless DUMB_ERROR_MESSAGES.include?(e.message) + raise e + end end end end diff --git a/config/environments/integration_1.rb b/config/environments/integration_1.rb deleted file mode 100644 index 042a23caa..000000000 --- a/config/environments/integration_1.rb +++ /dev/null @@ -1,39 +0,0 @@ - # Copyright (c) 2010-2011, Diaspora Inc. This file is -# licensed under the Affero General Public License version 3 or later. See -# the COPYRIGHT file. - -Diaspora::Application.configure do - # Settings specified here will take precedence over those in config/environment.rb - - # In the development environment your application's code is reloaded on - # every request. This slows down response time but is perfect for development - # since you don't have to restart the webserver when you make code changes. - config.cache_classes = false - - # Log error messages when you accidentally call methods on nil. - config.whiny_nils = true - - # Show full error reports and disable caching - config.consider_all_requests_local = true - config.action_controller.perform_caching = false - - # Don't care if the mailer can't send - config.action_mailer.raise_delivery_errors = false - config.active_support.deprecation = :log - - config.threadsafe! - - # Monkeypatch around the nasty "2.5MB exception page" issue, caused by very large environment vars - # This snippet via: http://stackoverflow.com/questions/3114993/exception-pages-in-development-mode-take-upwards-of-15-30-seconds-to-render-why - # Relevant Rails ticket: https://rails.lighthouseapp.com/projects/8994/tickets/5027-_request_and_responseerb-and-diagnosticserb-take-an-increasingly-long-time-to-render-in-development-with-multiple-show-tables-calls - config.after_initialize do - module SmallInspect - def inspect - "<#{self.class.name} - tooooo long>" - end - end - [ActionController::Base, ActionDispatch::RemoteIp::RemoteIpGetter, OmniAuth::Strategy, Warden::Proxy].each do |klazz| - klazz.send(:include, SmallInspect) - end - end -end diff --git a/lib/postzord/receiver/local_batch.rb b/lib/postzord/receiver/local_batch.rb index 45f0af1c0..f7bc5811f 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.class}:#{@object.guid}") + FEDERATION_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.class}:#{@object.guid}") + FEDERATION_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 8b1851408..3f2b97b69 100644 --- a/lib/postzord/receiver/private.rb +++ b/lib/postzord/receiver/private.rb @@ -28,7 +28,7 @@ class Postzord::Receiver::Private < Postzord::Receiver end rescue Exception => e #this sucks - FEDERATION_LOGGER.info("Failure to receive #{@object.class}:#{@object.id} for sender:#{@sender.id} for user:#{@user.id}: #{e.message}") + FEDERATION_LOGGER.info("Failure to receive #{@object.inspect} for sender:#{@sender.id} for user:#{@user.id}: #{e.message}") raise e end end @@ -53,7 +53,7 @@ class Postzord::Receiver::Private < Postzord::Receiver 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.class}:#{@object.guid}") + FEDERATION_LOGGER.info("user:#{@user.id} successfully received private post from person#{@sender.guid} #{@object.inspect}") obj end diff --git a/lib/postzord/receiver/public.rb b/lib/postzord/receiver/public.rb index 2955def04..ac92ca3cd 100644 --- a/lib/postzord/receiver/public.rb +++ b/lib/postzord/receiver/public.rb @@ -20,16 +20,15 @@ class Postzord::Receiver::Public < Postzord::Receiver # @return [void] def receive! - raise 'not valid signature' unless verified_signature? - raise 'unable to save object' unless save_object + return false unless verified_signature? + return false unless save_object - FEDERATION_LOGGER.info("received a #{@object.class}:#{@object.guid} with author #{@object.author.diaspora_handle}") + FEDERATION_LOGGER.info("received a #{@object.inspect}") if @object.respond_to?(:relayable?) receive_relayable elsif @object.is_a?(AccountDeletion) #nothing else - FEDERATION_LOGGER.info("queuing local batchjob") Resque.enqueue(Jobs::ReceiveLocalBatch, @object.class.to_s, @object.id, self.recipient_user_ids) true end diff --git a/lib/webfinger.rb b/lib/webfinger.rb index 6400789e6..180ec2df9 100644 --- a/lib/webfinger.rb +++ b/lib/webfinger.rb @@ -51,7 +51,7 @@ class Webfinger else person = make_person_from_webfinger end - FEDERATION_LOGGER.logger.info("successfully webfingered#{@account}") + FEDERATION_LOGGER.info("successfully webfingered#{@account}") person end