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..f947e7c0a 100644 --- a/app/models/jobs/base.rb +++ b/app/models/jobs/base.rb @@ -15,9 +15,8 @@ module Jobs begin yield rescue Exception => e - if DUMB_ERROR_MESSAGES.include?(e.message) - Rails.logger.error(e.message) - else + Rails.info("error in job: #{e.message}") + unless DUMB_ERROR_MESSAGES.include?(e.message) raise e 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/integration_1.rb b/config/environments/integration1.rb similarity index 98% rename from config/environments/integration_1.rb rename to config/environments/integration1.rb index 443bf1737..a3a5ee606 100644 --- a/config/environments/integration_1.rb +++ b/config/environments/integration1.rb @@ -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/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/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..f7bc5811f 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.inspect}") 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.inspect}") true end diff --git a/lib/postzord/receiver/private.rb b/lib/postzord/receiver/private.rb index 5efe118f7..3f2b97b69 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.inspect} 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.inspect}") 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..ac92ca3cd 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] @@ -21,6 +23,7 @@ class Postzord::Receiver::Public < Postzord::Receiver return false unless verified_signature? return false unless save_object + FEDERATION_LOGGER.info("received a #{@object.inspect}") if @object.respond_to?(:relayable?) receive_relayable elsif @object.is_a?(AccountDeletion) @@ -47,7 +50,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..180ec2df9 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.info("successfully webfingered#{@account}") person end