diff options
| -rw-r--r-- | Gemfile | 1 | ||||
| -rw-r--r-- | Gemfile.lock | 2 | ||||
| -rw-r--r-- | app/models/exim_log.rb | 129 | ||||
| -rw-r--r-- | app/models/info_request.rb | 6 | ||||
| -rw-r--r-- | app/models/mail_server_log.rb | 201 | ||||
| -rw-r--r-- | app/models/mail_server_log_done.rb (renamed from app/models/exim_log_done.rb) | 11 | ||||
| -rw-r--r-- | app/models/public_body.rb | 2 | ||||
| -rw-r--r-- | app/views/admin_request/show.rhtml | 10 | ||||
| -rw-r--r-- | config/crontab.ugly | 4 | ||||
| -rw-r--r-- | config/general.yml-example | 6 | ||||
| -rw-r--r-- | db/migrate/20121010214348_rename_exim_log_tables.rb | 13 | ||||
| -rw-r--r-- | doc/INSTALL-exim4.md | 2 | ||||
| -rw-r--r-- | doc/INSTALL-postfix.md | 28 | ||||
| -rw-r--r-- | lib/configuration.rb | 1 | ||||
| -rwxr-xr-x | script/check-recent-requests-sent | 2 | ||||
| -rwxr-xr-x | script/load-mail-server-logs (renamed from script/load-exim-logs) | 10 | ||||
| -rw-r--r-- | spec/lib/timezone_fixes_spec.rb | 18 | ||||
| -rw-r--r-- | spec/models/mail_server_log_spec.rb | 166 |
18 files changed, 452 insertions, 160 deletions
@@ -38,6 +38,7 @@ gem 'xapian-full-alaveteli', '~> 1.2.9.5' gem 'xml-simple' gem 'zip' gem 'capistrano' +gem 'syslog_protocol' group :test do gem 'fakeweb' diff --git a/Gemfile.lock b/Gemfile.lock index 35edac1e9..b3fa61708 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -93,6 +93,7 @@ GEM archive-tar-minitar (>= 0.5.2) test-unit (1.2.3) hoe (>= 1.5.1) + syslog_protocol (0.9.2) vpim (0.695) will_paginate (2.3.16) xapian-full-alaveteli (1.2.9.5) @@ -130,6 +131,7 @@ DEPENDENCIES ruby-debug19 ruby-msg (~> 1.5.0) test-unit (~> 1.2.3) + syslog_protocol vpim will_paginate (~> 2.3.11) xapian-full-alaveteli (~> 1.2.9.5) diff --git a/app/models/exim_log.rb b/app/models/exim_log.rb deleted file mode 100644 index abe198493..000000000 --- a/app/models/exim_log.rb +++ /dev/null @@ -1,129 +0,0 @@ -# == Schema Information -# Schema version: 114 -# -# Table name: exim_logs -# -# id :integer not null, primary key -# exim_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 -# - -# models/exim_log.rb: -# 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/ - -class EximLog < ActiveRecord::Base - belongs_to :info_request - belongs_to :exim_log_done - - # Load in exim 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. - def EximLog.load_file(file_name) - file_name_db = file_name - is_gz = false - if file_name.include?(".gz") - is_gz = true - file_name_db = file_name.gsub(".gz", "") - end - - modified = File::stat(file_name).mtime - raise "EximLog.load_file: file not found " + file_name if modified.nil? - - ActiveRecord::Base.transaction do - # see if we already have it - done = EximLogDone.find_by_filename(file_name_db) - if !done.nil? - if modified.utc == done.last_stat.utc - # already have that, nothing to do - return - end - EximLog.delete_all "exim_log_done_id = " + done.id.to_s - end - if !done - done = EximLogDone.new - done.filename = file_name_db - end - done.last_stat = modified - - # scan the file - if is_gz - f = Zlib::GzipReader.open(file_name) - else - f = File.open(file_name, 'r') - end - order = 0 - for line in f - order = order + 1 - email_domain = Configuration::incoming_email_domain - emails = line.scan(/request-[^\s]+@#{email_domain}/).sort.uniq - for email in emails - info_request = InfoRequest.find_by_incoming_email(email) - if !info_request.nil? - exim_log = EximLog.new - exim_log.info_request = info_request - exim_log.exim_log_done = done - exim_log.line = line - exim_log.order = order - exim_log.save! - end - end - end - - # update done structure so we know when we last read this file - done.save! - end - end - - # Check that the last day of requests has been sent in Exim 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 exim 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? - def EximLog.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 exim 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 - for ir in irs - # Look for line showing request was sent - found = false - for exim_log in ir.exim_logs - test_outgoing = " <= " + ir.incoming_email + " " - if exim_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 !exim_log.line.include?(envelope_from) - $stderr.puts("unexpected parsing of exim line: [#{exim_log.line.chomp}]") - else - found = true - end - end - end - if !found - # 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 Exim line for request id " + ir.id.to_s + " " + ir.url_title + " (check envelope from is being set to request address in Ruby, and load-exim-logs crontab is working)") # *** don't comment out this STDERR line, it is the point of the function! - ok = false - end - end - - return ok - end - -end - - - diff --git a/app/models/info_request.rb b/app/models/info_request.rb index 85168e6d4..d8c84fa9e 100644 --- a/app/models/info_request.rb +++ b/app/models/info_request.rb @@ -47,7 +47,7 @@ class InfoRequest < ActiveRecord::Base has_many :track_things, :order => 'created_at desc' has_many :comments, :order => 'created_at' has_many :censor_rules, :order => 'created_at desc' - has_many :exim_logs, :order => 'exim_log_done_id' + has_many :mail_server_logs, :order => 'mail_server_log_done_id' has_tag_string @@ -884,8 +884,8 @@ public info_request_event.track_things_sent_emails.each { |a| a.destroy } info_request_event.destroy end - self.exim_logs.each do |exim_log| - exim_log.destroy + self.mail_server_logs.each do |mail_server_log| + mail_server_log.destroy end self.outgoing_messages.each { |a| a.destroy } self.incoming_messages.each { |a| a.destroy } 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 + + + diff --git a/app/models/exim_log_done.rb b/app/models/mail_server_log_done.rb index 86574a4cd..3fb20f0b3 100644 --- a/app/models/exim_log_done.rb +++ b/app/models/mail_server_log_done.rb @@ -1,7 +1,7 @@ # == Schema Information -# Schema version: 114 +# Schema version: 20121010214348 # -# Table name: exim_log_dones +# Table name: mail_server_log_dones # # id :integer not null, primary key # filename :text not null @@ -10,14 +10,13 @@ # updated_at :datetime not null # -# models/exim_log_done.rb: -# Stores that a particular exim file has been loaded in, see exim_log.rb +# Stores that a particular mail server log file has been loaded in, see mail_server_log.rb # # Copyright (c) 2009 UK Citizens Online Democracy. All rights reserved. # Email: francis@mysociety.org; WWW: http://www.mysociety.org/ -class EximLogDone < ActiveRecord::Base - has_many :exim_logs +class MailServerLogDone < ActiveRecord::Base + has_many :mail_server_logs end diff --git a/app/models/public_body.rb b/app/models/public_body.rb index 34bcd332c..c70aff9b9 100644 --- a/app/models/public_body.rb +++ b/app/models/public_body.rb @@ -17,7 +17,7 @@ # notes :text default(""), not null # first_letter :string(255) not null # publication_scheme :text default(""), not null -# api_key :string(255) +# api_key :string(255) not null # info_requests_count :integer default(0), not null # diff --git a/app/views/admin_request/show.rhtml b/app/views/admin_request/show.rhtml index 9d939eb35..2541fd323 100644 --- a/app/views/admin_request/show.rhtml +++ b/app/views/admin_request/show.rhtml @@ -213,15 +213,15 @@ -<h2>Exim delivery logs</h2> +<h2>Mail server delivery logs</h2> <p><i>(Lines containing the request incoming email address, updated hourly.)</i></p> -<% for exim_log_done_id, exim_logs in @info_request.exim_logs.group_by(&:exim_log_done_id) %> - <!-- <h3><%=h exim_logs[0].exim_log_done.filename %></h3> --> - <pre><% for exim_log in exim_logs %><%=h exim_log.line%><% end %></pre> +<% for mail_server_log_done_id, mail_server_logs in @info_request.mail_server_logs.group_by(&:mail_server_log_done_id) %> + <!-- <h3><%=h mail_server_logs[0].mail_server_log_done.filename %></h3> --> + <pre><% for mail_server_log in mail_server_logs %><%=h mail_server_log.line%><% end %></pre> <% end %> -<% if @info_request.exim_logs.size == 0 %> +<% if @info_request.mail_server_logs.size == 0 %> <p>None (perhaps this is an old or a very new request)</p> <% end %> diff --git a/config/crontab.ugly b/config/crontab.ugly index 3e44f6153..894b464cf 100644 --- a/config/crontab.ugly +++ b/config/crontab.ugly @@ -16,8 +16,8 @@ MAILTO=cron-!!(*= $site *)!!@mysociety.org # Once an hour 09 * * * * !!(*= $user *)!! run-with-lockfile -n /data/vhost/!!(*= $vhost *)!!/alert-comment-on-request.lock /data/vhost/!!(*= $vhost *)!!/!!(*= $vcspath *)!!/script/alert-comment-on-request || echo "stalled?" -# Only root can read the exim log files -31 * * * * root run-with-lockfile -n /data/vhost/!!(*= $vhost *)!!/load-exim-logs.lock /data/vhost/!!(*= $vhost *)!!/!!(*= $vcspath *)!!/script/load-exim-logs || echo "stalled?" +# Only root can read the log files +31 * * * * root run-with-lockfile -n /data/vhost/!!(*= $vhost *)!!/load-mail-server-logs.lock /data/vhost/!!(*= $vhost *)!!/!!(*= $vcspath *)!!/script/load-mail-server-logs || echo "stalled?" # Once a day, early morning 23 4 * * * !!(*= $user *)!! run-with-lockfile -n /data/vhost/!!(*= $vhost *)!!/delete-old-things.lock /data/vhost/!!(*= $vhost *)!!/!!(*= $vcspath *)!!/script/delete-old-things || echo "stalled?" diff --git a/config/general.yml-example b/config/general.yml-example index b457b5ed6..9646e45c8 100644 --- a/config/general.yml-example +++ b/config/general.yml-example @@ -172,3 +172,9 @@ GA_CODE: '' # Search path for external commandline utilities (such as pdftohtml, pdftk, unrtf) UTILITY_SEARCH_PATH: ["/usr/bin", "/usr/local/bin"] + +# Path to your exim or postfix log files that will get sucked up by script/load-mail-server-logs +MTA_LOG_PATH: '/var/log/exim4/exim-mainlog-*' + +# Whether we are using "exim" or "postfix" for our MTA +MTA_LOG_TYPE: "exim" diff --git a/db/migrate/20121010214348_rename_exim_log_tables.rb b/db/migrate/20121010214348_rename_exim_log_tables.rb new file mode 100644 index 000000000..75fcff065 --- /dev/null +++ b/db/migrate/20121010214348_rename_exim_log_tables.rb @@ -0,0 +1,13 @@ +class RenameEximLogTables < ActiveRecord::Migration + def self.up + rename_table :exim_logs, :mail_server_logs + rename_table :exim_log_dones, :mail_server_log_dones + rename_column :mail_server_logs, :exim_log_done_id, :mail_server_log_done_id + end + + def self.down + rename_table :mail_server_logs, :exim_logs + rename_table :mail_server_log_dones, :exim_log_dones + rename_column :exim_logs, :mail_server_log_done_id, :exim_log_done_id + end +end diff --git a/doc/INSTALL-exim4.md b/doc/INSTALL-exim4.md index 91c3506d3..e37da14ff 100644 --- a/doc/INSTALL-exim4.md +++ b/doc/INSTALL-exim4.md @@ -11,7 +11,7 @@ In `/etc/exim4/conf.d/main/04_alaveteli_options`: (The user ALAVETELI_USER should have write permissions on ALAVETELI_HOME). Note that the name and location of the log files created by Exim must match -what the `load-exim-logs` script expects, hence the need for the extra +what the `load-mail-server-logs` script expects, hence the need for the extra `log_file_path` setting. And the `check-recent-requests-sent` scripts expects the logs to contain the `from=<...>` envelope information, so we make the logs more verbose with `log_selector`. diff --git a/doc/INSTALL-postfix.md b/doc/INSTALL-postfix.md index 70a2954bd..a73d67ce1 100644 --- a/doc/INSTALL-postfix.md +++ b/doc/INSTALL-postfix.md @@ -31,6 +31,34 @@ following to /etc/aliases: # We use this for envelope from for some messages where we don't care about delivery do-not-reply-to-this-address: :blackhole: +# Logging + +For the postfix logs to be read by the script 'load-mail-server-logs' succesfully they need to be log rotated with a date in the filename. Since that will create a lot of rotated log files (one for each day), it's good to have them in their own directory. For example (on Ubuntu) /etc/rsyslog.d/50-default.conf + + mail.* -/var/log/mail/mail.log + +And also edit /etc/logrotate.d/rsyslog: + + /var/log/mail/mail.log + { + rotate 30 + daily + dateext + missingok + notifempty + compress + delaycompress + sharedscripts + postrotate + reload rsyslog >/dev/null 2>&1 || true + endscript + } + +You'll also need to tell Alaveteli where the log files are stored and that they're in postfix format. Update config/general.yml with: + + MTA_LOG_PATH: '/var/log/mail/mail.log-*' + MTA_LOG_TYPE: "postfix" + # Troubleshooting To test mail delivery, run: diff --git a/lib/configuration.rb b/lib/configuration.rb index 5f761a1f6..ee2ce40c5 100644 --- a/lib/configuration.rb +++ b/lib/configuration.rb @@ -30,6 +30,7 @@ module Configuration :INCOMING_EMAIL_SECRET => 'dummysecret', :ISO_COUNTRY_CODE => 'GB', :MAX_REQUESTS_PER_USER_PER_DAY => nil, + :MTA_LOG_TYPE => 'exim', :NEW_RESPONSE_REMINDER_AFTER_DAYS => [3, 10, 24], :OVERRIDE_ALL_PUBLIC_BODY_REQUEST_EMAILS => '', :RAW_EMAILS_LOCATION => 'files/raw_emails', diff --git a/script/check-recent-requests-sent b/script/check-recent-requests-sent index 588c6b73a..7840dba4a 100755 --- a/script/check-recent-requests-sent +++ b/script/check-recent-requests-sent @@ -2,7 +2,7 @@ cd "`dirname "$0"`" -bundle exec ./runner 'EximLog.check_recent_requests_have_been_sent' +bundle exec ./runner 'MailServerLog.check_recent_requests_have_been_sent' diff --git a/script/load-exim-logs b/script/load-mail-server-logs index 00b6b9825..9ff7a1401 100755 --- a/script/load-exim-logs +++ b/script/load-mail-server-logs @@ -2,6 +2,10 @@ LOC=`dirname "$0"` +cd "$LOC"/.. +source commonlib/shlib/deployfns +read_conf config/general + # Specific file if specified if [ x$1 != x ] then @@ -10,14 +14,14 @@ then *) f=$(pwd)/$1 ;; esac cd "$LOC" - bundle exec ./runner 'EximLog.load_file("'$f'")' + bundle exec ./runner 'MailServerLog.load_file("'$f'")' exit fi # Load in last three days worth of logs (if they've been modified) cd "$LOC" -LATEST=$( ls /var/log/exim4/exim-mainlog-* 2>/dev/null | sort | tail -3 ) +LATEST=$( ls $OPTION_MTA_LOG_PATH 2>/dev/null | sort | tail -3 ) for X in $LATEST do - bundle exec ./runner 'EximLog.load_file("'$X'")' + bundle exec ./runner 'MailServerLog.load_file("'$X'")' done diff --git a/spec/lib/timezone_fixes_spec.rb b/spec/lib/timezone_fixes_spec.rb index eef7e865c..8dd1ff480 100644 --- a/spec/lib/timezone_fixes_spec.rb +++ b/spec/lib/timezone_fixes_spec.rb @@ -1,6 +1,6 @@ # This is a test of the monkey patches in timezone_fixes.rb -# We use EximLogDone here just as a totally random model that has a datetime type. +# We use MailServerLogDone here just as a totally random model that has a datetime type. require File.expand_path(File.dirname(__FILE__) + '/../spec_helper') @@ -10,8 +10,8 @@ describe "when doing things with timezones" do with_env_tz 'America/New_York' do with_active_record_default_timezone :utc do time = Time.local(2000) - exim_log_done = EximLogDone.create('last_stat' => time, 'filename' => 'dummy') - saved_time = EximLogDone.find(exim_log_done.id).last_stat + mail_server_log_done = MailServerLogDone.create('last_stat' => time, 'filename' => 'dummy') + saved_time = MailServerLogDone.find(mail_server_log_done.id).last_stat assert_equal time, saved_time assert_equal [0, 0, 0, 1, 1, 2000, 6, 1, false, "EST"], time.to_a assert_equal [0, 0, 5, 1, 1, 2000, 6, 1, false, "UTC"], saved_time.to_a @@ -24,8 +24,8 @@ describe "when doing things with timezones" do with_active_record_default_timezone :utc do Time.use_zone 'Central Time (US & Canada)' do time = Time.zone.local(2000) - exim_log_done = EximLogDone.create('last_stat' => time, 'filename' => 'dummy') - saved_time = EximLogDone.find(exim_log_done.id).last_stat + mail_server_log_done = MailServerLogDone.create('last_stat' => time, 'filename' => 'dummy') + saved_time = MailServerLogDone.find(mail_server_log_done.id).last_stat assert_equal time, saved_time assert_equal [0, 0, 0, 1, 1, 2000, 6, 1, false, "CST"], time.to_a assert_equal [0, 0, 6, 1, 1, 2000, 6, 1, false, "UTC"], saved_time.to_a @@ -39,8 +39,8 @@ describe "when doing things with timezones" do #it "should preserve time objects with UTC time conversion to default timezone local" do # with_env_tz 'America/New_York' do # time = Time.utc(2000) - # exim_log_done = EximLogDone.create('last_stat' => time, 'filename' => 'dummy') - # saved_time = EximLogDone.find(exim_log_done.id).last_stat + # mail_server_log_done = MailServerLogDone.create('last_stat' => time, 'filename' => 'dummy') + # saved_time = MailServerLogDone.find(mail_server_log_done.id).last_stat # assert_equal time, saved_time # assert_equal [0, 0, 0, 1, 1, 2000, 6, 1, false, "UTC"], time.to_a # assert_equal [0, 0, 19, 31, 12, 1999, 5, 365, false, "EST"], saved_time.to_a @@ -52,8 +52,8 @@ describe "when doing things with timezones" do with_active_record_default_timezone :local do Time.use_zone 'Central Time (US & Canada)' do time = Time.zone.local(2000) - exim_log_done = EximLogDone.create('last_stat' => time, 'filename' => 'dummy') - saved_time = EximLogDone.find(exim_log_done.id).last_stat + mail_server_log_done = MailServerLogDone.create('last_stat' => time, 'filename' => 'dummy') + saved_time = MailServerLogDone.find(mail_server_log_done.id).last_stat assert_equal time, saved_time assert_equal [0, 0, 0, 1, 1, 2000, 6, 1, false, "CST"], time.to_a assert_equal [0, 0, 1, 1, 1, 2000, 6, 1, false, "EST"], saved_time.to_a diff --git a/spec/models/mail_server_log_spec.rb b/spec/models/mail_server_log_spec.rb new file mode 100644 index 000000000..d0a1d202f --- /dev/null +++ b/spec/models/mail_server_log_spec.rb @@ -0,0 +1,166 @@ +require File.expand_path(File.dirname(__FILE__) + '/../spec_helper') + +describe MailServerLog do + describe ".load_file" do + before :each do + Configuration.stub!(:incoming_email_domain).and_return("example.com") + File.stub_chain(:stat, :mtime).and_return(DateTime.new(2012, 10, 10)) + end + + let(:log) {[ + "This is a line of a logfile relevant to foi+request-1234@example.com", + "This is the second line for the same foi+request-1234@example.com email address" + ]} + + let(:ir) { info_requests(:fancy_dog_request) } + + it "loads relevant lines of an uncompressed exim log file" do + File.should_receive(:open).with("/var/log/exim4/exim-mainlog-2012-10-10", "r").and_return(log) + InfoRequest.should_receive(:find_by_incoming_email).with("request-1234@example.com").twice.and_return(ir) + MailServerLog.load_file("/var/log/exim4/exim-mainlog-2012-10-10") + + ir.mail_server_logs.count.should == 2 + log = ir.mail_server_logs[0] + log.order.should == 1 + log.line.should == "This is a line of a logfile relevant to foi+request-1234@example.com" + + log = ir.mail_server_logs[1] + log.order.should == 2 + log.line.should == "This is the second line for the same foi+request-1234@example.com email address" + end + + it "doesn't load the log file twice if it's unchanged" do + File.should_receive(:open).with("/var/log/exim4/exim-mainlog-2012-10-10", "r").once.and_return([]) + + MailServerLog.load_file("/var/log/exim4/exim-mainlog-2012-10-10") + MailServerLog.load_file("/var/log/exim4/exim-mainlog-2012-10-10") + end + + it "loads the log file again if it's changed" do + File.should_receive(:open).with("/var/log/exim4/exim-mainlog-2012-10-10", "r").twice.and_return([]) + MailServerLog.load_file("/var/log/exim4/exim-mainlog-2012-10-10") + File.stub_chain(:stat, :mtime).and_return(DateTime.new(2012, 10, 11)) + MailServerLog.load_file("/var/log/exim4/exim-mainlog-2012-10-10") + end + + it "doesn't end up with two copies of each line when the same file is actually loaded twice" do + File.should_receive(:open).with("/var/log/exim4/exim-mainlog-2012-10-10", "r").twice.and_return(log) + InfoRequest.should_receive(:find_by_incoming_email).with("request-1234@example.com").any_number_of_times.and_return(ir) + + MailServerLog.load_file("/var/log/exim4/exim-mainlog-2012-10-10") + ir.mail_server_logs.count.should == 2 + + File.stub_chain(:stat, :mtime).and_return(DateTime.new(2012, 10, 11)) + MailServerLog.load_file("/var/log/exim4/exim-mainlog-2012-10-10") + ir.mail_server_logs.count.should == 2 + end + + it "easily handles gzip compress log files" do + File.should_not_receive(:open) + Zlib::GzipReader.should_receive(:open).with("/var/log/exim4/exim-mainlog-2012-10-10.gz").and_return([]) + MailServerLog.load_file("/var/log/exim4/exim-mainlog-2012-10-10.gz") + end + end + + describe ".email_addresses_on_line" do + before :each do + Configuration.stub!(:incoming_email_domain).and_return("example.com") + Configuration.stub!(:incoming_email_prefix).and_return("foi+") + end + + it "recognises a single incoming email" do + MailServerLog.email_addresses_on_line("a random log line foi+request-14-e0e09f97@example.com has an email").should == + ["foi+request-14-e0e09f97@example.com"] + end + + it "recognises two email addresses on the same line" do + MailServerLog.email_addresses_on_line("two email addresses here foi+request-10-1234@example.com and foi+request-14-e0e09f97@example.com").should == + ["foi+request-10-1234@example.com", "foi+request-14-e0e09f97@example.com"] + end + + it "returns an empty array when there is an email address from a different domain" do + MailServerLog.email_addresses_on_line("other foi+request-10-1234@foo.com").should be_empty + end + + it "ignores an email with a different prefix" do + MailServerLog.email_addresses_on_line("foitest+request-14-e0e09f97@example.com").should be_empty + end + + it "ignores an email where the . is substituted for something else" do + MailServerLog.email_addresses_on_line("foi+request-14-e0e09f97@exampledcom").should be_empty + end + end + + context "Postfix" do + let(:log) {[ +"Oct 3 16:39:35 host postfix/pickup[2257]: CB55836EE58C: uid=1003 from=<foitest+request-14-e0e09f97@example.com>", +"Oct 3 16:39:35 host postfix/cleanup[7674]: CB55836EE58C: message-id=<ogm-15+506bdda7a4551-20ee@example.com>", +"Oct 3 16:39:35 host postfix/qmgr[1673]: 9634B16F7F7: from=<foitest+request-10-1234@example.com>, size=368, nrcpt=1 (queue active)", +"Oct 3 16:39:35 host postfix/qmgr[15615]: CB55836EE58C: from=<foitest+request-14-e0e09f97@example.com>, size=1695, nrcpt=1 (queue active)", +"Oct 3 16:39:38 host postfix/smtp[7676]: CB55836EE58C: to=<foi@some.gov.au>, relay=aspmx.l.google.com[74.125.25.27]:25, delay=2.5, delays=0.13/0.02/1.7/0.59, dsn=2.0.0, status=sent (250 2.0.0 OK 1349246383 j9si1676296paw.328)", +"Oct 3 16:39:38 host postfix/smtp[1681]: 9634B16F7F7: to=<kdent@example.com>, relay=none, delay=46, status=deferred (connect to 216.150.150.131[216.150.150.131]: No route to host)", +"Oct 3 16:39:38 host postfix/qmgr[15615]: CB55836EE58C: removed", + ]} + + describe ".load_postfix_log_data" do + # Postfix logs for a single email go over multiple lines. They are all tied together with the Queue ID. + # See http://onlamp.com/onlamp/2004/01/22/postfix.html + it "loads the postfix log and untangles seperate email transactions using the queue ID" do + Configuration.stub!(:incoming_email_domain).and_return("example.com") + log.stub!(:rewind) + ir1 = info_requests(:fancy_dog_request) + ir2 = info_requests(:naughty_chicken_request) + InfoRequest.should_receive(:find_by_incoming_email).with("request-14-e0e09f97@example.com").any_number_of_times.and_return(ir1) + InfoRequest.should_receive(:find_by_incoming_email).with("request-10-1234@example.com").any_number_of_times.and_return(ir2) + MailServerLog.load_postfix_log_data(log, MailServerLogDone.new(:filename => "foo", :last_stat => DateTime.now)) + # TODO: Check that each log line is attached to the correct request + ir1.mail_server_logs.count.should == 5 + ir1.mail_server_logs[0].order.should == 1 + ir1.mail_server_logs[0].line.should == "Oct 3 16:39:35 host postfix/pickup[2257]: CB55836EE58C: uid=1003 from=<foitest+request-14-e0e09f97@example.com>" + ir1.mail_server_logs[1].order.should == 2 + ir1.mail_server_logs[1].line.should == "Oct 3 16:39:35 host postfix/cleanup[7674]: CB55836EE58C: message-id=<ogm-15+506bdda7a4551-20ee@example.com>" + ir1.mail_server_logs[2].order.should == 4 + ir1.mail_server_logs[2].line.should == "Oct 3 16:39:35 host postfix/qmgr[15615]: CB55836EE58C: from=<foitest+request-14-e0e09f97@example.com>, size=1695, nrcpt=1 (queue active)" + ir1.mail_server_logs[3].order.should == 5 + ir1.mail_server_logs[3].line.should == "Oct 3 16:39:38 host postfix/smtp[7676]: CB55836EE58C: to=<foi@some.gov.au>, relay=aspmx.l.google.com[74.125.25.27]:25, delay=2.5, delays=0.13/0.02/1.7/0.59, dsn=2.0.0, status=sent (250 2.0.0 OK 1349246383 j9si1676296paw.328)" + ir1.mail_server_logs[4].order.should == 7 + ir1.mail_server_logs[4].line.should == "Oct 3 16:39:38 host postfix/qmgr[15615]: CB55836EE58C: removed" + ir2.mail_server_logs.count.should == 2 + ir2.mail_server_logs[0].order.should == 3 + ir2.mail_server_logs[0].line.should == "Oct 3 16:39:35 host postfix/qmgr[1673]: 9634B16F7F7: from=<foitest+request-10-1234@example.com>, size=368, nrcpt=1 (queue active)" + ir2.mail_server_logs[1].order.should == 6 + ir2.mail_server_logs[1].line.should == "Oct 3 16:39:38 host postfix/smtp[1681]: 9634B16F7F7: to=<kdent@example.com>, relay=none, delay=46, status=deferred (connect to 216.150.150.131[216.150.150.131]: No route to host)" + end + end + + describe ".scan_for_postfix_queue_ids" do + it "returns the queue ids of interest with the connected email addresses" do + Configuration.stub!(:incoming_email_domain).and_return("example.com") + MailServerLog.scan_for_postfix_queue_ids(log).should == { + "CB55836EE58C" => ["request-14-e0e09f97@example.com"], + "9634B16F7F7" => ["request-10-1234@example.com"] + } + end + end + + describe ".extract_postfix_queue_id_from_syslog_line" do + it "returns nil if there is no queue id" do + MailServerLog.extract_postfix_queue_id_from_syslog_line("Oct 7 07:16:48 kedumba postfix/smtp[14294]: connect to mail.neilcopp.com.au[110.142.151.66]:25: Connection refused").should be_nil + end + end + + describe ".request_postfix_sent?" do + it "returns true when the logs say the message was sent" do + ir = info_requests(:fancy_dog_request) + ir.mail_server_logs.create!(:line => "Oct 10 16:58:38 kedumba postfix/smtp[26358]: A664436F218D: to=<contact@openaustraliafoundation.org.au>, relay=aspmx.l.google.com[74.125.25.26]:25, delay=2.7, delays=0.16/0.02/1.8/0.67, dsn=2.0.0, status=sent (250 2.0.0 OK 1349848723 e6si653316paw.346)", :order => 1) + MailServerLog.request_postfix_sent?(ir).should be_true + end + + it "returns false when the logs say the message hasn't been sent" do + ir = info_requests(:fancy_dog_request) + ir.mail_server_logs.create!(:line => "Oct 10 13:22:49 kedumba postfix/smtp[11876]: 6FB9036F1307: to=<foo@example.com>, relay=mta7.am0.yahoodns.net[74.6.136.244]:25, delay=1.5, delays=0.03/0/0.48/1, dsn=5.0.0, status=bounced (host mta7.am0.yahoodns.net[74.6.136.244] said: 554 delivery error: dd Sorry your message to foo@example.com cannot be delivered. This account has been disabled or discontinued [#102]. - mta1272.mail.sk1.yahoo.com (in reply to end of DATA command))", :order => 1) + MailServerLog.request_postfix_sent?(ir).should be_false + end + end + end +end |