diff options
31 files changed, 680 insertions, 179 deletions
@@ -30,7 +30,7 @@ gem 'rake', '~> 0.9.2.2' gem 'rspec', '~> 1.3.2' gem 'rspec-rails', '~> 1.3.4' gem 'ruby-msg', '~> 1.5.0' -gem 'test-unit', '~> 1.2.3' if RUBY_VERSION.to_f >= 1.9 +gem 'test-unit', '~> 1.2.3', :platforms => :ruby_19 gem 'vpim' gem 'will_paginate', '~> 2.3.11' # when 1.2.9 is released by the maintainer, we can stop using this fork: @@ -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' @@ -45,6 +46,7 @@ group :test do end group :develop do - gem 'ruby-debug' + gem 'ruby-debug', :platforms => :ruby_18 + gem 'ruby-debug19', :platforms => :ruby_19 gem 'annotate' end diff --git a/Gemfile.lock b/Gemfile.lock index f243ffaad..b3fa61708 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -25,6 +25,7 @@ GEM net-sftp (>= 2.0.0) net-ssh (>= 2.0.14) net-ssh-gateway (>= 1.1.0) + archive-tar-minitar (0.5.2) columnize (0.3.6) fakeweb (1.3.0) fast_gettext (0.6.8) @@ -32,9 +33,13 @@ GEM gettext (2.2.1) locale highline (1.6.13) + hoe (3.0.8) + rake (~> 0.8) json (1.5.4) linecache (0.46) rbx-require-relative (> 0.0.4) + linecache19 (0.5.12) + ruby_core_source (>= 0.1.4) locale (2.0.5) mahoro (0.3) memcache-client (1.8.5) @@ -72,10 +77,23 @@ GEM ruby-debug-base (~> 0.10.4.0) ruby-debug-base (0.10.4) linecache (>= 0.3) + ruby-debug-base19 (0.11.25) + columnize (>= 0.3.1) + linecache19 (>= 0.5.11) + ruby_core_source (>= 0.1.4) + ruby-debug19 (0.11.6) + columnize (>= 0.3.1) + linecache19 (>= 0.5.11) + ruby-debug-base19 (>= 0.11.19) ruby-msg (1.5.0) ruby-ole (>= 1.2.8) vpim (>= 0.360) ruby-ole (1.2.11.3) + ruby_core_source (0.1.5) + 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) @@ -110,7 +128,10 @@ DEPENDENCIES rspec (~> 1.3.2) rspec-rails (~> 1.3.4) ruby-debug + 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/controllers/general_controller.rb b/app/controllers/general_controller.rb index 150b433ec..21a318938 100644 --- a/app/controllers/general_controller.rb +++ b/app/controllers/general_controller.rb @@ -71,7 +71,9 @@ class GeneralController < ApplicationController def blog medium_cache @feed_autodetect = [] - @feed_url = "#{Configuration::blog_feed}?lang=#{self.locale_from_params()}" + @feed_url = Configuration::blog_feed + separator = @feed_url.include?('?') ? '&' : '?' + @feed_url = "#{@feed_url}#{separator}lang=#{self.locale_from_params()}" @blog_items = [] if not @feed_url.empty? content = quietly_try_to_open(@feed_url) 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/incoming_message.rb b/app/models/incoming_message.rb index fcb4671c5..367909f57 100644 --- a/app/models/incoming_message.rb +++ b/app/models/incoming_message.rb @@ -75,8 +75,7 @@ class IncomingMessage < ActiveRecord::Base # Documentation at http://i.loveruby.net/en/projects/tmail/doc/ def mail(force = nil) if (!force.nil? || @mail.nil?) && !self.raw_email.nil? - # Hack round bug in TMail's MIME decoding. Example request which provokes it: - # http://www.whatdotheyknow.com/request/reviews_of_unduly_lenient_senten#incoming-4830 + # Hack round bug in TMail's MIME decoding. # Report of TMail bug: # http://rubyforge.org/tracker/index.php?func=detail&aid=21810&group_id=4512&atid=17370 copy_of_raw_data = self.raw_email.data.gsub(/; boundary=\s+"/ims,'; boundary="') @@ -345,8 +344,7 @@ class IncomingMessage < ActiveRecord::Base name = Regexp.escape(self.info_request.user_name) # To end of message sections - # http://www.whatdotheyknow.com/request/university_investment_in_the_arm - text.gsub!(/^#{name}[^\n]+\nSent by:[^\n]+\n.*/ims, "\n\n" + replacement) + text.gsub!(/^\s?#{name}[^\n]+\n([^\n]+\n)?\s?Sent by:[^\n]+\n.*/ims, "\n\n" + replacement) # Some other sort of forwarding quoting # http://www.whatdotheyknow.com/request/224/response/326 @@ -580,7 +578,8 @@ class IncomingMessage < ActiveRecord::Base # Remove existing quoted sections folded_quoted_text = self.remove_lotus_quoting(text, 'FOLDED_QUOTED_SECTION') - folded_quoted_text = IncomingMessage.remove_quoted_sections(text, "FOLDED_QUOTED_SECTION") + folded_quoted_text = IncomingMessage.remove_quoted_sections(folded_quoted_text, "FOLDED_QUOTED_SECTION") + self.cached_main_body_text_unfolded = text self.cached_main_body_text_folded = folded_quoted_text self.save! 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/app/views/general/blog.rhtml b/app/views/general/blog.rhtml index a80f167d8..5f859fef8 100644 --- a/app/views/general/blog.rhtml +++ b/app/views/general/blog.rhtml @@ -45,7 +45,7 @@ <div id="left_column"> <h1><%=@title %></h1> - + <div id="blog"> <% for item in @blog_items: %> <div class="blog_post"> @@ -53,7 +53,9 @@ <p class="subtitle"><%= _("Posted on {{date}} by {{author}}", :date=>simple_date(Time.parse(item['pubDate'][0])), :author=>item['creator']) %></p> <div><%= item['encoded'] %></div> <p><em> + <% if item['comments'] %> <a href="<%=item['comments'][0]%>"><%= _("{{number_of_comments}} comments", :number_of_comments=>item['comments'][1]) %></a> + <% end %> </em> </p> </div> diff --git a/commonlib b/commonlib -Subproject 131375c752c02aa20f1644240fe69720275da42 +Subproject 3bf8c34eed89a946f981363eb862f25ac843769 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/environment.rb b/config/environment.rb index db537c14e..3ce887c03 100644 --- a/config/environment.rb +++ b/config/environment.rb @@ -1,5 +1,9 @@ # Be sure to restart your web server when you modify this file. +# the default encoding for IO is utf-8, and we use utf-8 internally +if RUBY_VERSION.to_f >= 1.9 + Encoding.default_external = Encoding.default_internal = Encoding::UTF_8 +end # Uncomment below to force Rails into production mode when # you don't control web/app server and can't set it the proper way 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/config/initializers/fast_gettext.rb b/config/initializers/fast_gettext.rb index 721c49cd0..2ecf5cb5d 100644 --- a/config/initializers/fast_gettext.rb +++ b/config/initializers/fast_gettext.rb @@ -1,4 +1,3 @@ -Encoding.default_external = 'UTF-8' if RUBY_VERSION.to_f >= 1.9 FastGettext.add_text_domain 'app', :path => File.join(Rails.root, 'locale'), :type => :po FastGettext.default_text_domain = 'app' diff --git a/config/initializers/missing_source_file.rb b/config/initializers/missing_source_file.rb new file mode 100644 index 000000000..a114fa972 --- /dev/null +++ b/config/initializers/missing_source_file.rb @@ -0,0 +1,2 @@ +# For Rails 2.3 on Ruby 1.9.3 @see https://github.com/rails/rails/pull/3745 +MissingSourceFile::REGEXPS << [/^cannot load such file -- (.+)$/i, 1] 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/controllers/api_controller_spec.rb b/spec/controllers/api_controller_spec.rb index ded9a040a..8d8a39950 100644 --- a/spec/controllers/api_controller_spec.rb +++ b/spec/controllers/api_controller_spec.rb @@ -1,3 +1,4 @@ +# coding: utf-8 require File.expand_path(File.dirname(__FILE__) + '/../spec_helper') def normalise_whitespace(s) @@ -167,7 +168,7 @@ describe ApiController, "when using the API" do OutgoingMessage.count.should == n_outgoing_messages end - it "should not allow other people’s requests to be updated" do + it "should not allow other people's requests to be updated" do request_id = _create_request n_incoming_messages = IncomingMessage.count n_outgoing_messages = OutgoingMessage.count diff --git a/spec/controllers/general_controller_spec.rb b/spec/controllers/general_controller_spec.rb index de8dd8422..cebcaf6ab 100644 --- a/spec/controllers/general_controller_spec.rb +++ b/spec/controllers/general_controller_spec.rb @@ -17,6 +17,22 @@ describe GeneralController, "when trying to show the blog" do end end +describe GeneralController, 'when getting the blog feed' do + + it 'should add a lang param correctly to a url with no querystring' do + Configuration.stub!(:blog_feed).and_return("http://blog.example.com") + get :blog + assigns[:feed_url].should == "http://blog.example.com?lang=en" + end + + it 'should add a lang param correctly to a url with an existing querystring' do + Configuration.stub!(:blog_feed).and_return("http://blog.example.com?alt=rss") + get :blog + assigns[:feed_url].should == "http://blog.example.com?alt=rss&lang=en" + end + +end + describe GeneralController, "when searching" do integrate_views diff --git a/spec/controllers/public_body_controller_spec.rb b/spec/controllers/public_body_controller_spec.rb index 9eca43aee..d12818a1c 100644 --- a/spec/controllers/public_body_controller_spec.rb +++ b/spec/controllers/public_body_controller_spec.rb @@ -1,3 +1,4 @@ +# coding: utf-8 require File.expand_path(File.dirname(__FILE__) + '/../spec_helper') describe PublicBodyController, "when showing a body" do diff --git a/spec/fixtures/files/lotus-notes-quoting.email b/spec/fixtures/files/lotus-notes-quoting.email new file mode 100644 index 000000000..863a2dfef --- /dev/null +++ b/spec/fixtures/files/lotus-notes-quoting.email @@ -0,0 +1,112 @@ +From foi@example.com Thu Mar 06 17:28:24 2008 +To: FOI Person <EMAIL_TO> +Subject: Re: Freedom of Information request +MIME-Version: 1.0 +X-Mailer: Lotus Notes Release 6.5.6 March 06, 2007 +From: foi <foi@example.com> +Date: Thu, 6 Mar 2008 17:31:51 +0000 +Content-Type: multipart/alternative; boundary="=_alternative 005FFC2E80257404_=" + +This is a multipart message in MIME format. +--=_alternative 005FFC2E80257404_= +Content-Type: text/plain; charset="ISO-8859-1" +Content-Transfer-Encoding: quoted-printable + +Dear Requester, + +Some text. + +Yours sincerely + + +FOI Team + + + +Bob Smith <request-xx-xxxxx@whatdotheyknow.com>=20 +Sent by: Bob Smith <request-xx-xxxxx@whatdotheyknow.com> +06/03/08 10:00 +Please respond to +Bob Smith <request-xx-xxxxx@whatdotheyknow.com> + + +To +FOI requests <foi@example.com> +cc + +Subject +Freedom of Information request + + + + + + + Original text + + + + +--=_alternative 005FFC2E80257404_= +Content-Type: text/html; charset="ISO-8859-1" +Content-Transfer-Encoding: quoted-printable + + +<div> +<br><font size=3D2 face=3D"Arial">Dear Requester,</font> +<br> +<br><font size=3D2 face=3D"Arial">Some text. </font> +<br> +<br><font size=3D2 face=3D"Arial">Yours sincerely</font> +<br> +<br> +<div> +<br><font size=3D2 face=3D"Arial">FOI Team</font> +<p> +<br> +<br> +<table width=3D100%> +<tr valign=3Dtop> +<td width=3D40%><font size=3D1 face=3D"sans-serif"><b>Bob Smith <re= +quest-xx-xxxxx@whatdotheyknow.com></b> +</font> +<br><font size=3D1 face=3D"sans-serif">Sent by: Bob Smith <request-= +bounce-xx-xxxxx@whatdotheyknow.com></font> +<p><font size=3D1 face=3D"sans-serif">06/03/08 10:00</font> +<table border> +<tr valign=3Dtop> +<td bgcolor=3Dwhite> +<div align=3Dcenter><font size=3D1 face=3D"sans-serif">Please respond to<br> +Bob Smith <request-xx-xxxxx@whatdotheyknow.com></font></div><= +/table> +<br> +<td width=3D59%> +<table width=3D100%> +<tr valign=3Dtop> +<td> +<div align=3Dright><font size=3D1 face=3D"sans-serif">To</font></div> +<td><font size=3D1 face=3D"sans-serif">FOI requests +<foi@example.com></font> +<tr valign=3Dtop> +<td> +<div align=3Dright><font size=3D1 face=3D"sans-serif">cc</font></div> +<td> +<tr valign=3Dtop> +<td> +<div align=3Dright><font size=3D1 face=3D"sans-serif">Subject</font></div> +<td><font size=3D1 face=3D"sans-serif">Freedom of Information request</font></table> +<br> +<table> +<tr valign=3Dtop> +<td> +<td></table> +<br></table> +<br> +<br> +<br><tt><font size=3D2> Original text<br> +<br> +<br> +</font></tt> +<br></div></div></div> +--=_alternative 005FFC2E80257404_=-- + diff --git a/spec/fixtures/files/space-boundary.email b/spec/fixtures/files/space-boundary.email new file mode 100644 index 000000000..37d65dbb5 --- /dev/null +++ b/spec/fixtures/files/space-boundary.email @@ -0,0 +1,37 @@ +From responder@example.com Wed Sep 03 10:44:18 2008 +Return-path: <responder@example.com> +Envelope-to: foi@sandwich.ukcod.org.uk +Delivery-date: Wed, 03 Sep 2008 10:44:18 +0100 +X-MimeOLE: Produced By Microsoft Exchange V6.5 +Content-class: urn:content-classes:message +MIME-Version: 1.0 +Content-Type: multipart/mixed; boundary= + "----_=_NextPart_001_01C90DA9.9B158D0D" +Subject: A subject +Date: Wed, 3 Sep 2008 10:44:05 +0100 +Message-ID: <D403C5D38B9BD6468928738951034DDE85A457@aglnex02.attorneygeneral.gsi.gov.uk> +X-MS-Has-Attach: yes +X-MS-TNEF-Correlator: +Thread-Topic: Freedom of Information request - An information request about + stuff +Thread-Index: AckNqOAr459KZB17Q1OIy1jxNVd9xAAAAnVAAAAWJ+A= +From: "A responder" <responder@example.com> +To: FOI Person <EMAIL_TO> + +This is a multi-part message in MIME format. + +------_=_NextPart_001_01C90DA9.9B158D0D +Content-Type: text/plain; charset="us-ascii" +Content-Transfer-Encoding: quoted-printable + +=20Apologies.=20Herewith. + +------_=_NextPart_001_01C90DA9.9B158D0D +Content-Type: application/octet-stream; name="Mr Gradwick.pdf" +Content-Transfer-Encoding: base64 +Content-Description: Mr Gradwick.pdf +Content-Disposition: attachment; filename="Mr Gradwick.pdf" + +xxx + +------_=_NextPart_001_01C90DA9.9B158D0D-- 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/incoming_message_spec.rb b/spec/models/incoming_message_spec.rb index cf84b4595..69a5da0e9 100644 --- a/spec/models/incoming_message_spec.rb +++ b/spec/models/incoming_message_spec.rb @@ -12,6 +12,14 @@ describe IncomingMessage, " when dealing with incoming mail" do ActionMailer::Base.deliveries.clear end + it 'should correctly parse multipart mails with a linebreak in the boundary marker' do + ir = info_requests(:fancy_dog_request) + receive_incoming_mail('space-boundary.email', ir.incoming_email) + message = ir.incoming_messages[1] + message.mail.parts.size.should == 2 + message.mail.multipart?.should == true + end + it "should return the mail Date header date for sent at" do @im.parse_raw_email!(true) @im.reload @@ -60,7 +68,6 @@ describe IncomingMessage, " when dealing with incoming mail" do is not good utf-8' do ir = info_requests(:fancy_dog_request) receive_incoming_mail('no-part-charset-bad-utf8.email', ir.incoming_email) - puts ir.incoming_messages.inspect message = ir.incoming_messages[1] message.parse_raw_email! message.get_main_body_text_internal.should include("The above text was badly encoded") @@ -125,16 +132,23 @@ end describe IncomingMessage, " folding quoted parts of emails" do - it "cope with [ in user names properly" do - @user = mock_model(User) - @user.stub!(:name).and_return("Sir [ Bobble") - @info_request = mock_model(InfoRequest) - @info_request.stub!(:user).and_return(@user) - @info_request.stub!(:user_name).and_return(@user.name) + it 'should fold an example lotus notes quoted part converted from HTML correctly' do + ir = info_requests(:fancy_dog_request) + receive_incoming_mail('lotus-notes-quoting.email', ir.incoming_email) + message = ir.incoming_messages[1] + message.get_main_body_text_folded.should match(/FOLDED_QUOTED_SECTION/) + end + it 'should fold a plain text lotus notes quoted part correctly' do + text = "FOI Team\n\n\nInfo Requester <xxx@whatdotheyknow.com>=20\nSent by: Info Requester <request-bounce-xxxxx@whatdotheyknow.com>\n06/03/08 10:00\nPlease respond to\nInfo Requester <request-xxxx@whatdotheyknow.com>" @incoming_message = IncomingMessage.new() - @incoming_message.info_request = @info_request + @incoming_message.stub_chain(:info_request, :user_name).and_return("Info Requester") + @incoming_message.remove_lotus_quoting(text).should match(/FOLDED_QUOTED_SECTION/) + end + it "cope with [ in user names properly" do + @incoming_message = IncomingMessage.new() + @incoming_message.stub_chain(:info_request, :user_name).and_return("Sir [ Bobble") # this gives a warning if [ is in the name text = @incoming_message.remove_lotus_quoting("Sir [ Bobble \nSent by: \n") text.should == "\n\nFOLDED_QUOTED_SECTION" 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 |