Add logging statements, rescue callbacks in em-webfinger

app/controllers/people_controller.rb

@@ -104,15 +104,11 @@ class PeopleController < ApplicationController
   def webfinger(account, opts = {})
     finger = EMWebfinger.new(account)
     finger.on_person do |response|
-      begin
-        if response.class == Person
-          response.socket_to_uid(current_user.id, opts)
-        else
-          require File.join(Rails.root,'lib/diaspora/websocket')
-          Diaspora::WebSocket.queue_to_user(current_user.id, {:class => 'people', :status => 'fail', :query => account, :response => response}.to_json)
-        end
-      rescue RuntimeError => e
-        puts e.message
+      if response.class == Person
+        response.socket_to_uid(current_user.id, opts)
+      else
+        require File.join(Rails.root,'lib/diaspora/websocket')
+        Diaspora::WebSocket.queue_to_user(current_user.id, {:class => 'people', :status => 'fail', :query => account, :response => response}.to_json)
       end
     end
   end

app/models/user.rb

@@ -243,18 +243,18 @@ class User
     # person.owner will always return a ProxyObject.
     # calling nil? performs a necessary evaluation.
     unless person.owner.nil?
+      Rails.logger.debug("event=push_to_person route=local sender=#{self.inspect} recipient=#{person.inspect} payload_type=#{post.class}")
       person.owner.receive(post.to_diaspora_xml, self.person)
     else
       xml = salmon.xml_for person
-
-      Rails.logger.debug("#{self.real_name} is adding xml to message queue to #{person.receive_url}")
+      Rails.logger.debug("event=push_to_person route=remote sender=#{self.inspect} recipient=#{person.inspect} payload_type=#{post.class}")
       QUEUE.add_post_request(person.receive_url, xml)
       QUEUE.process
     end
   end
 
   def push_to_hub(post)
-    Rails.logger.debug("Pushing update to pubsub server #{APP_CONFIG[:pubsub_server]} with url #{self.public_url}")
+    Rails.logger.debug("event=push_to_hub target=#{APP_CONFIG[:pubsub_server]} sender_url=#{self.public_url}")
     QUEUE.add_hub_notification(APP_CONFIG[:pubsub_server], self.public_url)
   end
 
@@ -280,18 +280,20 @@ class User
     if comment.save
       comment
     else
-      Rails.logger.warn "this failed to save: #{comment.inspect}"
+      Rails.logger.warn "event=build_comment status=save_failure user=#{self.inspect} comment=#{comment.inspect}"
       false
     end
   end
 
   def dispatch_comment(comment)
     if owns? comment.post
+      Rails.logger.info "event=dispatch_comment direction=downstream user=#{self.inspect} comment=#{comment.inspect}"
       comment.post_creator_signature = comment.sign_with_key(encryption_key)
       comment.save
       aspects = aspects_with_post(comment.post_id)
       push_to_people(comment, people_in_aspects(aspects))
     elsif owns? comment
+      Rails.logger.info "event=dispatch_comment direction=upstream user=#{self.inspect} comment=#{comment.inspect}"
       comment.save
       push_to_people comment, [comment.post.person]
     end

lib/diaspora/user/receiving.rb

@@ -22,8 +22,7 @@ module Diaspora
 
       def receive xml, salmon_author
         object = Diaspora::Parser.from_xml(xml)
-        Rails.logger.debug("Receiving object for #{self.real_name}:\n#{object.inspect}")
-        Rails.logger.debug("From: #{object.diaspora_handle}")
+        Rails.logger.debug("event=receive recipient=#{self.inspect} object=#{object.inspect} sender=#{salmon_author.inspect}")
         
         if object.is_a?(Request)
           salmon_author.save
@@ -46,13 +45,10 @@ module Diaspora
           e.on_person do |person|
             if person.class == Person
               object.person = person if object.respond_to? :person=
-
               unless object.is_a?(Request) || self.contact_for(salmon_author)
                 raise "Not connected to that person" 
               else
-
                 return receive_object(object,person)
-
               end
             end
 
@@ -164,7 +160,6 @@ module Diaspora
         end
 
         post.socket_to_uid(id, :aspect_ids => aspects.map{|x| x.id}) if (post.respond_to?(:socket_to_uid) && !self.owns?(post))
-
       end
     end
   end

lib/em-webfinger.rb

@@ -7,6 +7,7 @@ class EMWebfinger
     @account = account.strip.gsub('acct:','').to_s
     @callbacks = []
     @ssl = true 
+    Rails.logger.info("event=EMWebfinger status=initialized target=#{account}")
     # Raise an error if identifier has a port number 
     #raise "Identifier is invalid" if(@account.strip.match(/\:\d+$/))
     # Raise an error if identifier is not a valid email (generous regexp)
@@ -76,7 +77,14 @@ class EMWebfinger
 
 
   def process_callbacks(person)
-    @callbacks.each { |c| c.call(person) }
+    @callbacks.each { |c|
+      begin
+        c.call(person)
+      rescue Exception => e
+        Rails.logger.info("event=EMWebfinger status=error_on_callback error=#{e.inspect}")
+      end
+    }
+    Rails.logger.info("event=EMWebfinger status=complete person=#{person.inspect}")
   end