Defect #21226

Some log messages are missing the "MailHandler" prefix

Added by Deoren Moor about 3 years ago. Updated about 3 years ago.

Status:ClosedStart date:
Priority:NormalDue date:
Assignee:Jean-Philippe Lang% Done:

0%

Category:Email receiving
Target version:3.2.0
Resolution:Fixed Affected version:3.1.1

Description

For email scraping we set RAILS_ENV to development to increase logging details. This allows us to diagnose the various scraping issues we encounter and work around them.

Other scraping failures from what I can tell include the MailHandler: prefix before the error message. Either by intention, or a nice side effect, having that prefix in the log file allows for parsing of the log file by reporting scripts.

Today I encountered a scraping issue due to the contents of an email exceeding the limits of the description column. Here is an example entry in the log from that failed scraping attempt:

An unexpected error occurred when receiving email: Mysql2::Error: Data too long for column 'description' at row 1: INSERT INTO `issues` (`project_id`, `author_id`, `priority_id`, `tracker_$
Message 30130 can not be processed

This entry is missing the MailHandler: prefix that I am accustomed to seeing. Is this by design or is it really missing the prefix?

Associated revisions

Revision 14880
Added by Jean-Philippe Lang about 3 years ago

Fixed that some mail handler log messages are not prepended with "MailHandler:" (#21226).

History

#1 Updated by Toshi MARUYAMA about 3 years ago

Could you try this patch?

diff --git a/app/models/mail_handler.rb b/app/models/mail_handler.rb
--- a/app/models/mail_handler.rb
+++ b/app/models/mail_handler.rb
@@ -177,7 +177,7 @@ class MailHandler < ActionMailer::Base
     end
   rescue ActiveRecord::RecordInvalid => e
     # TODO: send a email to the user
-    logger.error e.message if logger
+    logger.error "MailHandler: #{e.message}" if logger
     false
   rescue MissingInformation => e
     logger.error "MailHandler: missing information from #{user}: #{e.message}" if logger

#2 Updated by Deoren Moor about 3 years ago

When I saw your patch I was very optimistic that it would work, but so far I don't see any change. I applied it and confirmed that the change matches what you've shown above:

root@help:/opt/redmine# svn diff

Index: app/models/mail_handler.rb
===================================================================
--- app/models/mail_handler.rb  (revision 14618)
+++ app/models/mail_handler.rb  (working copy)
@@ -177,7 +177,7 @@
     end
   rescue ActiveRecord::RecordInvalid => e
     # TODO: send a email to the user
-    logger.error e.message if logger
+    logger.error "MailHandler: #{e.message}" if logger
     false
   rescue MissingInformation => e
     logger.error "MailHandler: missing information from #{user}: #{e.message}" if logger

and then I had the script scrape the 1MB email. I looked in the log and found that the line is still missing the prefix (line break between the two entries manually added):

root@help:/opt/redmine# grep -E 'unexpected error|can not be processed' log/development.log | cut -c 1-190

An unexpected error occurred when receiving email: Mysql2::Error: Data too long for column 'description' at row 1: INSERT INTO `issues` (`project_id`, `author_id`, `priority_id`, `tracker_id
Message 5696 can not be processed

An unexpected error occurred when receiving email: Mysql2::Error: Data too long for column 'description' at row 1: INSERT INTO `issues` (`project_id`, `author_id`, `priority_id`, `tracker_id
Message 5697 can not be processed

#3 Updated by Jean-Philippe Lang about 3 years ago

This is an SQL error, not a ActiveRecord::RecordInvalid error. That's why it doesn't fix your problem.
Could you try this:

### Eclipse Workspace Patch 1.0
#P trunk
Index: app/models/mail_handler.rb
===================================================================
--- app/models/mail_handler.rb    (revision 14858)
+++ app/models/mail_handler.rb    (working copy)
@@ -54,7 +54,7 @@
   def self.safe_receive(*args)
     receive(*args)
   rescue Exception => e
-    logger.error "An unexpected error occurred when receiving email: #{e.message}" if logger
+    logger.error "MailHandler: an unexpected error occurred when receiving email: #{e.message}" if logger
     return false
   end

#4 Updated by Jean-Philippe Lang about 3 years ago

  • Assignee set to Jean-Philippe Lang
  • Target version set to 3.2.0

#5 Updated by Jean-Philippe Lang about 3 years ago

We could use tagged logging for the mail handler to make sure that everything is prepended with something like [MailHandler]. But that would apply to all log messages, including template renderings and stuff like that, making it harder to catch usefull log messages:

Current log message:

  Rendered mailer/_issue.text.erb (7.0ms)
  Rendered mailer/issue_add.text.erb within layouts/mailer (13.0ms)
  Rendered mailer/_issue.html.erb (6.0ms)
  Rendered mailer/issue_add.html.erb within layouts/mailer (7.0ms)

Sent email "[OnlineStore - Bug #15] (Resolved) New ticket on a given project" (4ms)
  bcc: jsmith@somenet.foo
MailHandler: issue #15 created by John Smith

Received mail (635.0ms)

With tagged logging:

[MailHandler]   Rendered mailer/_issue.text.erb (7.0ms)
[MailHandler]   Rendered mailer/issue_add.text.erb within layouts/mailer (12.0ms)
[MailHandler]   Rendered mailer/_issue.html.erb (6.0ms)
[MailHandler]   Rendered mailer/issue_add.html.erb within layouts/mailer (7.0ms)
[MailHandler] 
Sent email "[OnlineStore - Bug #15] (Resolved) New ticket on a given project" (3ms)
  bcc: jsmith@somenet.foo
[MailHandler] issue #15 created by John Smith
[MailHandler] 
Received mail (628.0ms)

#6 Updated by Jean-Philippe Lang about 3 years ago

  • Subject changed from Log messages are missing the "MailHandler" prefix when an email is rejected for containing more text than will fit in the description field to Some log messages are missing the "MailHandler" prefix
  • Status changed from New to Resolved
  • Resolution set to Fixed

Both patches are committed in r14880.
I would still like to hear from you about the tagged logging solution.

#7 Updated by Deoren Moor about 3 years ago

Jean-Philippe Lang wrote:

Both patches are committed in r14880.

Thanks!

I would still like to hear from you about the tagged logging solution.

If there is existing functionality (similar to syslog daemons) to filter on severity that could come in handy, otherwise I agree with your comment that tagging every line would make it more difficult to catch useful details.

I could see in a case where syslog functionality is available that MailHandler could be just one prefix used in the logging setup and that other "components" (for the lack of the correct word) would have their own prefix. Then if error messages were filtered to a separate file having the MailHandler prefix on all lines might prove useful.

Is there any existing functionality like that already in Redmine?

#8 Updated by Deoren Moor about 3 years ago

Jean-Philippe Lang wrote:

This is an SQL error, not a ActiveRecord::RecordInvalid error. That's why it doesn't fix your problem.
Could you try this:

[...]

It worked as you expected:

MailHandler: an unexpected error occurred when receiving email: Mysql2::Error: Data too long for column 'description' at row 1: INSERT INTO `issues` (`project_id`, `author_id`, `priority_id

Thanks.

#9 Updated by Jean-Philippe Lang about 3 years ago

  • Status changed from Resolved to Closed

Thanks for the feedback, I'm closing it.

Deoren Moor wrote:

Is there any existing functionality like that already in Redmine?

Rails logger can be configured to send logs to syslog but as far as I know, everything goes a single log file by default.

Also available in: Atom PDF