https://www.redmine.org/https://www.redmine.org/favicon.ico?16793021292015-11-13T04:16:13ZRedmineRedmine - Defect #21226: Some log messages are missing the "MailHandler" prefixhttps://www.redmine.org/issues/21226?journal_id=672792015-11-13T04:16:13ZToshi MARUYAMA
<ul></ul><p>Could you try this patch?</p>
<pre><code class="diff syntaxhl"><span class="gh">diff --git a/app/models/mail_handler.rb b/app/models/mail_handler.rb
</span><span class="gd">--- a/app/models/mail_handler.rb
</span><span class="gi">+++ b/app/models/mail_handler.rb
</span><span class="p">@@ -177,7 +177,7 @@</span> class MailHandler < ActionMailer::Base
end
rescue ActiveRecord::RecordInvalid => e
# TODO: send a email to the user
<span class="gd">- logger.error e.message if logger
</span><span class="gi">+ logger.error "MailHandler: #{e.message}" if logger
</span> false
rescue MissingInformation => e
logger.error "MailHandler: missing information from #{user}: #{e.message}" if logger
</code></pre> Redmine - Defect #21226: Some log messages are missing the "MailHandler" prefixhttps://www.redmine.org/issues/21226?journal_id=672912015-11-13T15:56:20ZDeoren Moor
<ul></ul><p>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:</p>
<p><code>root@help:/opt/redmine# svn diff</code><br /><pre><code class="diff syntaxhl"><span class="gh">Index: app/models/mail_handler.rb
===================================================================
</span><span class="gd">--- app/models/mail_handler.rb (revision 14618)
</span><span class="gi">+++ app/models/mail_handler.rb (working copy)
</span><span class="p">@@ -177,7 +177,7 @@</span>
end
rescue ActiveRecord::RecordInvalid => e
# TODO: send a email to the user
<span class="gd">- logger.error e.message if logger
</span><span class="gi">+ logger.error "MailHandler: #{e.message}" if logger
</span> false
rescue MissingInformation => e
logger.error "MailHandler: missing information from #{user}: #{e.message}" if logger
</code></pre></p>
<p>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):</p>
<p><code>root@help:/opt/redmine# grep -E 'unexpected error|can not be processed' log/development.log | cut -c 1-190</code><br /><pre>
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
</pre></p>
<pre>
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
</pre> Redmine - Defect #21226: Some log messages are missing the "MailHandler" prefixhttps://www.redmine.org/issues/21226?journal_id=673102015-11-14T10:59:02ZJean-Philippe Langjp_lang@yahoo.fr
<ul></ul><p>This is an SQL error, not a ActiveRecord::RecordInvalid error. That's why it doesn't fix your problem.<br />Could you try this:</p>
<pre><code class="diff syntaxhl"><span class="err">###</span> Eclipse Workspace Patch 1.0
<span class="err">#P</span> trunk
<span class="gh">Index: app/models/mail_handler.rb
===================================================================
</span><span class="gd">--- app/models/mail_handler.rb (revision 14858)
</span><span class="gi">+++ app/models/mail_handler.rb (working copy)
</span><span class="p">@@ -54,7 +54,7 @@</span>
def self.safe_receive(*args)
receive(*args)
rescue Exception => e
<span class="gd">- logger.error "An unexpected error occurred when receiving email: #{e.message}" if logger
</span><span class="gi">+ logger.error "MailHandler: an unexpected error occurred when receiving email: #{e.message}" if logger
</span> return false
end
</code></pre> Redmine - Defect #21226: Some log messages are missing the "MailHandler" prefixhttps://www.redmine.org/issues/21226?journal_id=673112015-11-14T11:08:57ZJean-Philippe Langjp_lang@yahoo.fr
<ul><li><strong>Assignee</strong> set to <i>Jean-Philippe Lang</i></li><li><strong>Target version</strong> set to <i>3.2.0</i></li></ul> Redmine - Defect #21226: Some log messages are missing the "MailHandler" prefixhttps://www.redmine.org/issues/21226?journal_id=673122015-11-14T11:27:27ZJean-Philippe Langjp_lang@yahoo.fr
<ul></ul><p>We could use <a href="http://api.rubyonrails.org/classes/ActiveSupport/TaggedLogging.html" class="external">tagged logging</a> 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:</p>
<p>Current log message:</p>
<pre>
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)
</pre>
<p>With tagged logging:</p>
<pre>
[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)
</pre> Redmine - Defect #21226: Some log messages are missing the "MailHandler" prefixhttps://www.redmine.org/issues/21226?journal_id=673132015-11-14T11:36:22ZJean-Philippe Langjp_lang@yahoo.fr
<ul><li><strong>Subject</strong> changed from <i>Log messages are missing the "MailHandler" prefix when an email is rejected for containing more text than will fit in the description field</i> to <i>Some log messages are missing the "MailHandler" prefix</i></li><li><strong>Status</strong> changed from <i>New</i> to <i>Resolved</i></li><li><strong>Resolution</strong> set to <i>Fixed</i></li></ul><p>Both patches are committed in <a class="changeset" title="Fixed that some mail handler log messages are not prepended with "MailHandler:" (#21226)." href="https://www.redmine.org/projects/redmine/repository/svn/revisions/14880">r14880</a>.<br />I would still like to hear from you about the tagged logging solution.</p> Redmine - Defect #21226: Some log messages are missing the "MailHandler" prefixhttps://www.redmine.org/issues/21226?journal_id=674402015-11-21T17:17:11ZDeoren Moor
<ul></ul><p>Jean-Philippe Lang wrote:</p>
<blockquote>
<p>Both patches are committed in <a class="changeset" title="Fixed that some mail handler log messages are not prepended with "MailHandler:" (#21226)." href="https://www.redmine.org/projects/redmine/repository/svn/revisions/14880">r14880</a>.</p>
</blockquote>
<p>Thanks!</p>
<blockquote>
<p>I would still like to hear from you about the tagged logging solution.</p>
</blockquote>
<p>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.</p>
<p>I could see in a case where syslog functionality <em>is</em> available that <code>MailHandler</code> 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 <code>MailHandler</code> prefix on all lines might prove useful.</p>
<p>Is there any existing functionality like that already in Redmine?</p> Redmine - Defect #21226: Some log messages are missing the "MailHandler" prefixhttps://www.redmine.org/issues/21226?journal_id=674582015-11-23T17:52:09ZDeoren Moor
<ul></ul><p>Jean-Philippe Lang wrote:</p>
<blockquote>
<p>This is an SQL error, not a ActiveRecord::RecordInvalid error. That's why it doesn't fix your problem.<br />Could you try this:</p>
<p>[...]</p>
</blockquote>
<p>It worked as you expected:</p>
<pre>
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
</pre>
<p>Thanks.</p> Redmine - Defect #21226: Some log messages are missing the "MailHandler" prefixhttps://www.redmine.org/issues/21226?journal_id=674822015-11-24T19:31:56ZJean-Philippe Langjp_lang@yahoo.fr
<ul><li><strong>Status</strong> changed from <i>Resolved</i> to <i>Closed</i></li></ul><p>Thanks for the feedback, I'm closing it.</p>
<p>Deoren Moor wrote:</p>
<blockquote>
<p>Is there any existing functionality like that already in Redmine?</p>
</blockquote>
<p>Rails logger can be configured to send logs to syslog but as far as I know, everything goes a single log file by default.</p>