Defect #21226
closedSome log messages are missing the "MailHandler" prefix
0%
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?
Updated by Toshi MARUYAMA almost 9 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
Updated by Deoren Moor almost 9 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
Updated by Jean-Philippe Lang almost 9 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
Updated by Jean-Philippe Lang almost 9 years ago
- Assignee set to Jean-Philippe Lang
- Target version set to 3.2.0
Updated by Jean-Philippe Lang almost 9 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)
Updated by Jean-Philippe Lang almost 9 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.
Updated by Deoren Moor over 8 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?
Updated by Deoren Moor over 8 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.
Updated by Jean-Philippe Lang over 8 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.