Commit b6c46b3f authored by Benjamin Neff's avatar Benjamin Neff Committed by Dennis Schubert
Browse files

add logging mixin and replace federation-logger

parent 1b77258d
......@@ -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
......
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
......@@ -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
......
......@@ -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
......@@ -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
......
......@@ -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
......
......@@ -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'
......
......@@ -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
......
# a logging mixin providing the logger
module Diaspora
module Logging
private
def logger
@logger ||= ::Logging::Logger[self]
end
end
end
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
#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
......@@ -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
......
......@@ -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
......
......@@ -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
......
......@@ -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
......
......@@ -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
......
Markdown is supported
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment