federation logger now in place.

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

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)
 

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

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

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
 

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

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

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

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

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

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

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
 

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

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<Integer>] User ids

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