Merge remote-tracking branch 'openaustralia_github/postfix_log_support' into develop

Conflicts:
  Gemfile.lock
  app/models/exim_log.rb

18 files changed, 452 insertions, 160 deletions

diff --git a/Gemfile b/Gemfile
index 0b0814479..92f9ac172 100644
--- a/Gemfile
+++ b/Gemfile
@@ -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