app/models/mail_server_log.rb
# == Schema Information
# Schema version: 20210114161442
#
# 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
# delivery_status :string
#
# 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: hello@mysociety.org; WWW: http://www.mysociety.org/
class MailServerLog < ApplicationRecord
# `serialize` needs to be called before all other ActiveRecord code.
# See http://stackoverflow.com/a/15610692/387558
serialize :delivery_status, DeliveryStatusSerializer
belongs_to :info_request,
inverse_of: :mail_server_logs
belongs_to :mail_server_log_done,
inverse_of: :mail_server_logs
before_create :calculate_delivery_status
# 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 self.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
if modified.nil?
raise "MailServerLog.load_file: file not found " + file_name
end
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.where("mail_server_log_done_id = ?", done.id).delete_all
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(AlaveteliConfiguration.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
f.close
end
end
# Scan the file
def self.load_exim_log_data(f, done)
order = 0
f.each do |line|
order += 1
create_exim_log_line(line, done, order)
end
end
def self.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|
sanitised_line = scrub(line)
order += 1
queue_id = extract_postfix_queue_id_from_syslog_line(sanitised_line)
if emails.key?(queue_id)
create_mail_server_logs(emails[queue_id], sanitised_line, order, done)
end
end
end
def self.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.key?(queue_id)
result[queue_id] = (result[queue_id] + emails).uniq
end
result
end
# Returns nil if there is no queue id
def self.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 self.email_addresses_on_line(line)
prefix = Regexp.quote(AlaveteliConfiguration.incoming_email_prefix)
domain = Regexp.quote(AlaveteliConfiguration.incoming_email_domain)
line.scan(/#{prefix}request-[^\s]+@#{domain}/).sort.uniq
end
def self.request_sent?(ir)
case(AlaveteliConfiguration.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 self.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 self.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.
# TODO: 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 successfully sent.
#
def self.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)
info_requests = InfoRequest.where("created_at < ?
AND created_at > ?
AND user_id IS NOT null",
Time.zone.now - 2.days,
Time.zone.now - 10.days)
# Go through each request and check it
ok = true
info_requests.each do |info_request|
unless request_sent?(info_request)
# It's very important the envelope from is set for avoiding spam filter reasons - this
# effectively acts as a check for that.
# *** don't comment out this STDERR line, it is the point of the function!
$stderr.puts("failed to find request sending in MTA logs for request " \
"id #{info_request.id} #{info_request.url_title} (check " \
"envelope from is being set to request address in Ruby, " \
"and load-mail-server-logs crontab is working)")
ok = false
end
end
ok
end
def self.create_exim_log_line(line, done, order = 1)
sanitised_line = scrub(line)
emails = email_addresses_on_line(sanitised_line)
create_mail_server_logs(emails, sanitised_line, order, done)
end
def is_owning_user?(user)
info_request.is_owning_user?(user)
end
# Public: Overrides the ActiveRecord attribute accessor
#
# opts = Hash of options (default: {})
# :redact - Redacts potentially sensitive information from the line
# :decorate - Wrap the line in a decorator appropriate to the MTA
#
# Returns a String, EximLine or PostfixLine
def line(opts = {})
_line = read_attribute(:line)
if opts[:redact]
_line = strip_syslog_prefix(_line)
_line = redact_hostname(_line) if sent_to_smarthost?(_line)
_line =
redact_idhash(_line, info_request.idhash) if info_request.try(:idhash)
end
_line = line_decorator.new(_line) if opts[:decorate]
_line
end
def delivery_status
unless attributes['delivery_status'].present?
# attempt to parse the status from the log line and store if successful
set_delivery_status
end
DeliveryStatusSerializer.load(read_attribute(:delivery_status))
# TODO: This rescue can be removed when there are no more cached
# MTA-specific statuses
rescue ArgumentError
warn %q(MailServerLog#delivery_status rescuing from invalid delivery
status. Run bundle exec rake temp:cache_delivery_status to update
cached values. This error handling will be removed soon.).
squish unless Rails.env.test?
# re-try setting the delivery status, forcing the write by avoiding the
# Rails 4.2 call to old_attribute_value hidden inside write_attribute as
# that will re-raise the 'Invalid delivery status' ArgumentError we're
# attempting to rescue
# https://apidock.com/rails/v4.2.7/ActiveRecord/AttributeMethods/Dirty/write_attribute
set_delivery_status(true)
save!
DeliveryStatusSerializer.load(read_attribute(:delivery_status))
end
private
# attempt to parse the status from the log line and store if successful
def set_delivery_status(force = false)
decorated = line(decorate: true)
if decorated && decorated.delivery_status
if force
force_delivery_status(decorated.delivery_status)
else
self.delivery_status = decorated.delivery_status
end
end
end
def force_delivery_status(new_status)
# write the value without checking the old (invalid) value, avoiding the
# unintended ArgumentError caused by reading the old value
update_columns(delivery_status: new_status)
# record the new value in `changes` so that save will have something to do
# as update_columns just updates the value
delivery_status_will_change!
end
def calculate_delivery_status
delivery_status
true
end
def self.create_mail_server_logs(emails, line, order, done)
emails.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)
end
end
end
private_class_method :create_mail_server_logs
def line_decorator
mta = AlaveteliConfiguration.mta_log_type.to_sym
case mta
when :exim
EximLine
when :postfix
PostfixLine
else
raise "Unexpected MTA type: #{ mta }"
end
end
def strip_syslog_prefix(line)
prefix_regexp = /\A(.*?\s)\d{4}-\d{2}-\d{2}\s\d{2}:\d{2}:\d{2}.*/
match = line.match(prefix_regexp).try(:[], 1)
if match
line.gsub(match, '')
else
line
end
end
def sent_to_smarthost?(line)
line.match(/R=(\w+)/).try(:[], 1).to_s.downcase == 'send_to_smarthost'
end
def redact_hostname(line)
hostname_regexp = /H=(.*?\s\[\d{1,3}\.\d{1,3}\.\d{1,3}\.\d{1,3}\]\:\d{1,5})/
match = line.match(hostname_regexp).try(:[], 1)
if match
line.gsub(match, _('[REDACTED]'))
else
line
end
end
def redact_idhash(line, idhash)
line.gsub(idhash, _('[REDACTED]'))
end
end