diff options
Diffstat (limited to 'app/models/mail_server_log.rb')
| -rw-r--r-- | app/models/mail_server_log.rb | 201 |
1 files changed, 201 insertions, 0 deletions
diff --git a/app/models/mail_server_log.rb b/app/models/mail_server_log.rb new file mode 100644 index 000000000..755584b90 --- /dev/null +++ b/app/models/mail_server_log.rb @@ -0,0 +1,201 @@ +# == Schema Information +# Schema version: 20121010214348 +# +# Table name: mail_server_logs +# +# id :integer not null, primary key +# mail_server_log_done_id :integer +# info_request_id :integer +# order :integer not null +# line :text not null +# created_at :datetime not null +# updated_at :datetime not null +# + +# We load log file lines for requests in here, for display in the admin interface. +# +# Copyright (c) 2009 UK Citizens Online Democracy. All rights reserved. +# Email: francis@mysociety.org; WWW: http://www.mysociety.org/ +# +# $Id: exim_log.rb,v 1.14 2009-09-17 21:10:05 francis Exp $ + +class MailServerLog < ActiveRecord::Base + belongs_to :info_request + belongs_to :mail_server_log_done + + # Load in exim or postfix log file from disk, or update if we already have it + # Assumes files are named with date, rather than cyclically. + # Doesn't do anything if file hasn't been modified since it was last loaded. + # Note: If you do use rotated log files (rather than files named by date), at some + # point old loaded log lines will get deleted in the database. + def MailServerLog.load_file(file_name) + is_gz = file_name.include?(".gz") + file_name_db = is_gz ? file_name.gsub(".gz", "") : file_name + + modified = File.stat(file_name).mtime + raise "MailServerLog.load_file: file not found " + file_name if modified.nil? + + ActiveRecord::Base.transaction do + # see if we already have it + done = MailServerLogDone.find_by_filename(file_name_db) + if done + if modified.utc == done.last_stat.utc + # already have that, nothing to do + return + else + MailServerLog.delete_all "mail_server_log_done_id = " + done.id.to_s + end + else + done = MailServerLogDone.new(:filename => file_name_db) + end + done.last_stat = modified + # update done structure so we know when we last read this file + done.save! + + f = is_gz ? Zlib::GzipReader.open(file_name) : File.open(file_name, 'r') + case(Configuration::mta_log_type.to_sym) + when :exim + load_exim_log_data(f, done) + when :postfix + load_postfix_log_data(f, done) + else + raise "Unexpected MTA type: #{type}" + end + end + end + + # Scan the file + def MailServerLog.load_exim_log_data(f, done) + order = 0 + f.each do |line| + order = order + 1 + emails = email_addresses_on_line(line) + for email in emails + info_request = InfoRequest.find_by_incoming_email(email) + if info_request + info_request.mail_server_logs.create!(:line => line, :order => order, :mail_server_log_done => done) + else + puts "Warning: Could not find request with email #{email}" + end + end + end + end + + def MailServerLog.load_postfix_log_data(f, done) + order = 0 + emails = scan_for_postfix_queue_ids(f) + # Go back to the beginning of the file + f.rewind + f.each do |line| + order = order + 1 + queue_id = extract_postfix_queue_id_from_syslog_line(line) + if emails.has_key?(queue_id) + emails[queue_id].each do |email| + info_request = InfoRequest.find_by_incoming_email(email) + if info_request + info_request.mail_server_logs.create!(:line => line, :order => order, :mail_server_log_done => done) + else + puts "Warning: Could not find request with email #{email}" + end + end + end + end + end + + def MailServerLog.scan_for_postfix_queue_ids(f) + result = {} + f.each do |line| + emails = email_addresses_on_line(line) + queue_id = extract_postfix_queue_id_from_syslog_line(line) + result[queue_id] = [] unless result.has_key?(queue_id) + result[queue_id] = (result[queue_id] + emails).uniq + end + result + end + + # Retuns nil if there is no queue id + def MailServerLog.extract_postfix_queue_id_from_syslog_line(line) + # Assume the log file was written using syslog and parse accordingly + m = SyslogProtocol.parse("<13>" + line).content.match(/^\S+: (\S+):/) + m[1] if m + end + + # We also check the email prefix so that we could, for instance, separately handle a staging and production + # instance running on the same server with different email prefixes. + def MailServerLog.email_addresses_on_line(line) + prefix = Regexp::quote(Configuration::incoming_email_prefix) + domain = Regexp::quote(Configuration::incoming_email_domain) + line.scan(/#{prefix}request-[^\s]+@#{domain}/).sort.uniq + end + + def MailServerLog.request_sent?(ir) + case(Configuration::mta_log_type.to_sym) + when :exim + request_exim_sent?(ir) + when :postfix + request_postfix_sent?(ir) + else + raise "Unexpected MTA type: #{type}" + end + end + + # Look at the log for a request and check that an email was delivered + def MailServerLog.request_exim_sent?(ir) + # Look for line showing request was sent + found = false + ir.mail_server_logs.each do |mail_server_log| + test_outgoing = " <= " + ir.incoming_email + " " + if mail_server_log.line.include?(test_outgoing) + # Check the from value is the same (it always will be, but may as well + # be sure we are parsing the exim line right) + envelope_from = " from <" + ir.incoming_email + "> " + if !mail_server_log.line.include?(envelope_from) + $stderr.puts("unexpected parsing of exim line: [#{mail_server_log.line.chomp}]") + else + found = true + end + end + end + found + end + + def MailServerLog.request_postfix_sent?(ir) + # dsn=2.0.0 is the magic word that says that postfix delivered the email + # See http://tools.ietf.org/html/rfc3464 + ir.mail_server_logs.any? { |l| l.line.include?("dsn=2.0.0") } + end + + # Check that the last day of requests has been sent in Exim or Postfix and we got the + # lines. Writes any errors to STDERR. This check is really mainly to + # check the envelope from is the request address, as Ruby is quite + # flaky with regard to that, and it is important for anti-spam reasons. + # XXX does this really check that, as the log just wouldn't pick + # up at all if the requests weren't sent that way as there would be + # no request- email in it? + # + # NB: There can be several emails involved in a request. This just checks that + # at least one of them has been succesfully sent. + # + def MailServerLog.check_recent_requests_have_been_sent + # Get all requests sent for from 2 to 10 days ago. The 2 day gap is + # because we load mail server log lines via cron at best an hour after they + # are made) + irs = InfoRequest.find(:all, :conditions => [ "created_at < ? and created_at > ? and user_id is not null", Time.now() - 2.day, Time.now() - 10.days ] ) + + # Go through each request and check it + ok = true + irs.each do |ir| + unless request_sent?(ir) + # It's very important the envelope from is set for avoiding spam filter reasons - this + # effectively acts as a check for that. + $stderr.puts("failed to find request sending in MTA logs for request id " + ir.id.to_s + " " + ir.url_title + " (check envelope from is being set to request address in Ruby, and load-mail-server-logs crontab is working)") # *** don't comment out this STDERR line, it is the point of the function! + ok = false + end + end + ok + end + +end + + + |