You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-user@logging.apache.org by Matej Vitásek <ve...@gmail.com> on 2013/05/09 14:32:03 UTC
Two problems with SMTPAppender
Hi all,
I'd like to report 2 problems I am encountering using the SMTPAppender. I
am using it* to send me mails whenever an ERROR is logged in a web
application.
1) Buffer size is ignored. Excerpt from my log4j2.xml:
<SMTP name="Mail" suppressExceptions="false" subject="Error Log"
to="..." from="..." smtpHost="smtp.gmail.com"
smtpPort="465" *bufferSize="10"* smtpProtocol="smtps" smtpUsername="..."
smtpPassword="...">
</SMTP>
You will notice that the buffer size is 10. I'd expect to be getting
e-mails with 10 errors aggregated, but every e-mail always contains only
one error.
Looking into SMTPAppender.append() I see a call to manager.sendEvents()
which does not aggregate the message - it just sends it. To me it seems
that append() should write into SMTPManager.buffer and send only if it's
full...
2) Sending the e-mail blocks the thread that logged the error. I don't know
how to "prove" this empirically, it's just a really clear subjective
feeling: whenever an error gets logged, the whole application just lags for
the time it takes to send the mail.
Can I provide you some help in pinpointing this problem?
Overall: just ask if you need more information,
Thanks!
Matej
Re: Two problems with SMTPAppender
Posted by Ralph Goers <rg...@apache.org>.
Your understanding is correct. The intention is to include the last n log events in the email when an error occurs, regardless of their log level. This is often useful for debugging. I believe this behavior carried over from either log4j 1.x or logback - I'm not really sure since someone else wrote this Appender.
It is a bit "different" from other appenders, and I am not crazy about that.
Ralph
On May 10, 2013, at 12:36 AM, Matej Vitásek <ve...@gmail.com> wrote:
> Thanks Remko,
>
> I understand it much better now. However, this one still eludes me: if you
> look into AppenderControl.callAppender(), there is a line like this:
>
> if (appender instanceof Filterable && ((Filterable)
> appender).isFiltered(event)) {
> return;
> }
>
> If I understand it correctly, it checks if the event is filtered OUT (BTW,
> it should be made clear in docs/JavaDoc that isFiltered == true ===
> filtered OUT), and if so, it does not proceed to log it:
> try {
> appender.append(event);
>
> Now, SMTPAppender overrides this isFiltered() and in it, it adds to the
> cyclic buffer! The only addition to the buffer happens when the
> SMTPAppender has determined that the event should be filtered out! :) Or am
> I reading it wrong? :)
>
>
> I will raise a JIRA ticket.
>
>
> Thanks again!
>
>
> Matej
>
>
> On Fri, May 10, 2013 at 9:27 AM, Remko Popma <re...@yahoo.com> wrote:
>
>> Matej,
>>
>> Suppose you have 3 threads that all log an error at exactly the same time.
>> They all call isFiltered at the same time, and all events are added to the
>> buffer before any thread had a chance to call the append method.
>> Now all three threads will call the append method. The first time, 3
>> events are grabbed from the buffer (leaving the buffer empty), and all
>> events are put into a single email which is sent immediately.
>> When the second thread calls append, the buffer is empty and no mail is
>> sent.
>> Same for thread#3.
>> (Hmm... This may be a bug? Currently the code does not check if the array
>> obtained from the buffer is empty and will send an empty email in this
>> case... )
>>
>> Anyway, I think the above flow was the intention.
>>
>> I understand your request now: you want multiple log events to be
>> collected into a single email if they arrive within some time window of the
>> first event.
>> Makes sense. Can you raise a Jira ticket for that?
>>
>> About your second issue, you can wrap the smtp appender in an async
>> appender so your app is not delayed by the network I/O.
>> See the docs for AsynchAppender.
>> (Note that this appender is renamed to AsyncAppender in beta6 which just
>> came out.)
>>
>>
>> Sent from my iPhone
>>
>> On 2013/05/10, at 15:56, Matej Vitásek <ve...@gmail.com> wrote:
>>
>>> Remko,
>>>
>>> Thanks for the answer. After looking into the sources some more I found
>>> this:
>>>
>>> - SMTPAppender.append(), which seems to be the usual way of events
>> being
>>> logged to this appender, sends the mail directly.
>>> - SMTPAppender.isFiltered(), which is an overriding of the usual logic
>>> "filtered => do not log", instead collects the events in the cyclic
>> buffer.
>>>
>>> To be honest, I am quite confused with this behavior. Could you perhaps
>>> shed some light on it?
>>>
>>> Regarding buffering mails and having 1 error not sent for a long time: I
>>> see your point, there can be perhaps a timeout setting.
>>>
>>> Rationale: way too often, errors are clustered together. More often than
>>> not, my app will send a barrage of error mails, and then be quiet for a
>>> while. Even a timeout of 1 second would decrease the mail traffic
>>> substantially, without losing any information.
>>>
>>> What is your opinion of my second problem, the app being blocked while
>> the
>>> mail is being sent?
>>>
>>> Thanks!
>>>
>>>
>>> Matej
>>>
>>>
>>>
>>> On Thu, May 9, 2013 at 2:48 PM, Remko Popma <re...@yahoo.com> wrote:
>>>
>>>> Matej,
>>>>
>>>> The docs may not be clear on this, but i believe this buffer is
>>>> essentially for multithreaded access.
>>>>
>>>> Every event will be stored in the buffer, and then trigger a send(). You
>>>> are right that sending happens in the calling thread. You could consider
>>>> wrapping the smtp appender in an async appender.
>>>>
>>>> When a send happens, it will grab all events currently in the buffer and
>>>> send them in a single email.
>>>>
>>>> I believe this is correct behavior. Otherwise you may only have one
>> ERROR
>>>> and the email never gets sent because the appender is waiting for 9 more
>>>> events...
>>>>
>>>> Best regards,
>>>> Remko
>>>>
>>>> Sent from my iPhone
>>>>
>>>> On 2013/05/09, at 21:32, Matej Vitásek <ve...@gmail.com> wrote:
>>>>
>>>>> Hi all,
>>>>>
>>>>> I'd like to report 2 problems I am encountering using the
>> SMTPAppender. I
>>>>> am using it* to send me mails whenever an ERROR is logged in a web
>>>>> application.
>>>>>
>>>>> 1) Buffer size is ignored. Excerpt from my log4j2.xml:
>>>>> <SMTP name="Mail" suppressExceptions="false" subject="Error Log"
>>>>> to="..." from="..." smtpHost="smtp.gmail.com"
>>>>> smtpPort="465" *bufferSize="10"* smtpProtocol="smtps"
>> smtpUsername="..."
>>>>> smtpPassword="...">
>>>>> </SMTP>
>>>>>
>>>>> You will notice that the buffer size is 10. I'd expect to be getting
>>>>> e-mails with 10 errors aggregated, but every e-mail always contains
>> only
>>>>> one error.
>>>>>
>>>>> Looking into SMTPAppender.append() I see a call to manager.sendEvents()
>>>>> which does not aggregate the message - it just sends it. To me it seems
>>>>> that append() should write into SMTPManager.buffer and send only if
>> it's
>>>>> full...
>>>>>
>>>>> 2) Sending the e-mail blocks the thread that logged the error. I don't
>>>> know
>>>>> how to "prove" this empirically, it's just a really clear subjective
>>>>> feeling: whenever an error gets logged, the whole application just lags
>>>> for
>>>>> the time it takes to send the mail.
>>>>>
>>>>> Can I provide you some help in pinpointing this problem?
>>>>>
>>>>>
>>>>> Overall: just ask if you need more information,
>>>>>
>>>>>
>>>>> Thanks!
>>>>>
>>>>>
>>>>> Matej
>>>>
>>>> ---------------------------------------------------------------------
>>>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>
>>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: Two problems with SMTPAppender
Posted by Matej Vitásek <ve...@gmail.com>.
Thanks Remko,
I understand it much better now. However, this one still eludes me: if you
look into AppenderControl.callAppender(), there is a line like this:
if (appender instanceof Filterable && ((Filterable)
appender).isFiltered(event)) {
return;
}
If I understand it correctly, it checks if the event is filtered OUT (BTW,
it should be made clear in docs/JavaDoc that isFiltered == true ===
filtered OUT), and if so, it does not proceed to log it:
try {
appender.append(event);
Now, SMTPAppender overrides this isFiltered() and in it, it adds to the
cyclic buffer! The only addition to the buffer happens when the
SMTPAppender has determined that the event should be filtered out! :) Or am
I reading it wrong? :)
I will raise a JIRA ticket.
Thanks again!
Matej
On Fri, May 10, 2013 at 9:27 AM, Remko Popma <re...@yahoo.com> wrote:
> Matej,
>
> Suppose you have 3 threads that all log an error at exactly the same time.
> They all call isFiltered at the same time, and all events are added to the
> buffer before any thread had a chance to call the append method.
> Now all three threads will call the append method. The first time, 3
> events are grabbed from the buffer (leaving the buffer empty), and all
> events are put into a single email which is sent immediately.
> When the second thread calls append, the buffer is empty and no mail is
> sent.
> Same for thread#3.
> (Hmm... This may be a bug? Currently the code does not check if the array
> obtained from the buffer is empty and will send an empty email in this
> case... )
>
> Anyway, I think the above flow was the intention.
>
> I understand your request now: you want multiple log events to be
> collected into a single email if they arrive within some time window of the
> first event.
> Makes sense. Can you raise a Jira ticket for that?
>
> About your second issue, you can wrap the smtp appender in an async
> appender so your app is not delayed by the network I/O.
> See the docs for AsynchAppender.
> (Note that this appender is renamed to AsyncAppender in beta6 which just
> came out.)
>
>
> Sent from my iPhone
>
> On 2013/05/10, at 15:56, Matej Vitásek <ve...@gmail.com> wrote:
>
> > Remko,
> >
> > Thanks for the answer. After looking into the sources some more I found
> > this:
> >
> > - SMTPAppender.append(), which seems to be the usual way of events
> being
> > logged to this appender, sends the mail directly.
> > - SMTPAppender.isFiltered(), which is an overriding of the usual logic
> > "filtered => do not log", instead collects the events in the cyclic
> buffer.
> >
> > To be honest, I am quite confused with this behavior. Could you perhaps
> > shed some light on it?
> >
> > Regarding buffering mails and having 1 error not sent for a long time: I
> > see your point, there can be perhaps a timeout setting.
> >
> > Rationale: way too often, errors are clustered together. More often than
> > not, my app will send a barrage of error mails, and then be quiet for a
> > while. Even a timeout of 1 second would decrease the mail traffic
> > substantially, without losing any information.
> >
> > What is your opinion of my second problem, the app being blocked while
> the
> > mail is being sent?
> >
> > Thanks!
> >
> >
> > Matej
> >
> >
> >
> > On Thu, May 9, 2013 at 2:48 PM, Remko Popma <re...@yahoo.com> wrote:
> >
> >> Matej,
> >>
> >> The docs may not be clear on this, but i believe this buffer is
> >> essentially for multithreaded access.
> >>
> >> Every event will be stored in the buffer, and then trigger a send(). You
> >> are right that sending happens in the calling thread. You could consider
> >> wrapping the smtp appender in an async appender.
> >>
> >> When a send happens, it will grab all events currently in the buffer and
> >> send them in a single email.
> >>
> >> I believe this is correct behavior. Otherwise you may only have one
> ERROR
> >> and the email never gets sent because the appender is waiting for 9 more
> >> events...
> >>
> >> Best regards,
> >> Remko
> >>
> >> Sent from my iPhone
> >>
> >> On 2013/05/09, at 21:32, Matej Vitásek <ve...@gmail.com> wrote:
> >>
> >>> Hi all,
> >>>
> >>> I'd like to report 2 problems I am encountering using the
> SMTPAppender. I
> >>> am using it* to send me mails whenever an ERROR is logged in a web
> >>> application.
> >>>
> >>> 1) Buffer size is ignored. Excerpt from my log4j2.xml:
> >>> <SMTP name="Mail" suppressExceptions="false" subject="Error Log"
> >>> to="..." from="..." smtpHost="smtp.gmail.com"
> >>> smtpPort="465" *bufferSize="10"* smtpProtocol="smtps"
> smtpUsername="..."
> >>> smtpPassword="...">
> >>> </SMTP>
> >>>
> >>> You will notice that the buffer size is 10. I'd expect to be getting
> >>> e-mails with 10 errors aggregated, but every e-mail always contains
> only
> >>> one error.
> >>>
> >>> Looking into SMTPAppender.append() I see a call to manager.sendEvents()
> >>> which does not aggregate the message - it just sends it. To me it seems
> >>> that append() should write into SMTPManager.buffer and send only if
> it's
> >>> full...
> >>>
> >>> 2) Sending the e-mail blocks the thread that logged the error. I don't
> >> know
> >>> how to "prove" this empirically, it's just a really clear subjective
> >>> feeling: whenever an error gets logged, the whole application just lags
> >> for
> >>> the time it takes to send the mail.
> >>>
> >>> Can I provide you some help in pinpointing this problem?
> >>>
> >>>
> >>> Overall: just ask if you need more information,
> >>>
> >>>
> >>> Thanks!
> >>>
> >>>
> >>> Matej
> >>
> >> ---------------------------------------------------------------------
> >> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> >> For additional commands, e-mail: log4j-user-help@logging.apache.org
> >>
> >>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
>
Re: Two problems with SMTPAppender
Posted by Remko Popma <re...@yahoo.com>.
Matej,
Suppose you have 3 threads that all log an error at exactly the same time.
They all call isFiltered at the same time, and all events are added to the buffer before any thread had a chance to call the append method.
Now all three threads will call the append method. The first time, 3 events are grabbed from the buffer (leaving the buffer empty), and all events are put into a single email which is sent immediately.
When the second thread calls append, the buffer is empty and no mail is sent.
Same for thread#3.
(Hmm... This may be a bug? Currently the code does not check if the array obtained from the buffer is empty and will send an empty email in this case... )
Anyway, I think the above flow was the intention.
I understand your request now: you want multiple log events to be collected into a single email if they arrive within some time window of the first event.
Makes sense. Can you raise a Jira ticket for that?
About your second issue, you can wrap the smtp appender in an async appender so your app is not delayed by the network I/O.
See the docs for AsynchAppender.
(Note that this appender is renamed to AsyncAppender in beta6 which just came out.)
Sent from my iPhone
On 2013/05/10, at 15:56, Matej Vitásek <ve...@gmail.com> wrote:
> Remko,
>
> Thanks for the answer. After looking into the sources some more I found
> this:
>
> - SMTPAppender.append(), which seems to be the usual way of events being
> logged to this appender, sends the mail directly.
> - SMTPAppender.isFiltered(), which is an overriding of the usual logic
> "filtered => do not log", instead collects the events in the cyclic buffer.
>
> To be honest, I am quite confused with this behavior. Could you perhaps
> shed some light on it?
>
> Regarding buffering mails and having 1 error not sent for a long time: I
> see your point, there can be perhaps a timeout setting.
>
> Rationale: way too often, errors are clustered together. More often than
> not, my app will send a barrage of error mails, and then be quiet for a
> while. Even a timeout of 1 second would decrease the mail traffic
> substantially, without losing any information.
>
> What is your opinion of my second problem, the app being blocked while the
> mail is being sent?
>
> Thanks!
>
>
> Matej
>
>
>
> On Thu, May 9, 2013 at 2:48 PM, Remko Popma <re...@yahoo.com> wrote:
>
>> Matej,
>>
>> The docs may not be clear on this, but i believe this buffer is
>> essentially for multithreaded access.
>>
>> Every event will be stored in the buffer, and then trigger a send(). You
>> are right that sending happens in the calling thread. You could consider
>> wrapping the smtp appender in an async appender.
>>
>> When a send happens, it will grab all events currently in the buffer and
>> send them in a single email.
>>
>> I believe this is correct behavior. Otherwise you may only have one ERROR
>> and the email never gets sent because the appender is waiting for 9 more
>> events...
>>
>> Best regards,
>> Remko
>>
>> Sent from my iPhone
>>
>> On 2013/05/09, at 21:32, Matej Vitásek <ve...@gmail.com> wrote:
>>
>>> Hi all,
>>>
>>> I'd like to report 2 problems I am encountering using the SMTPAppender. I
>>> am using it* to send me mails whenever an ERROR is logged in a web
>>> application.
>>>
>>> 1) Buffer size is ignored. Excerpt from my log4j2.xml:
>>> <SMTP name="Mail" suppressExceptions="false" subject="Error Log"
>>> to="..." from="..." smtpHost="smtp.gmail.com"
>>> smtpPort="465" *bufferSize="10"* smtpProtocol="smtps" smtpUsername="..."
>>> smtpPassword="...">
>>> </SMTP>
>>>
>>> You will notice that the buffer size is 10. I'd expect to be getting
>>> e-mails with 10 errors aggregated, but every e-mail always contains only
>>> one error.
>>>
>>> Looking into SMTPAppender.append() I see a call to manager.sendEvents()
>>> which does not aggregate the message - it just sends it. To me it seems
>>> that append() should write into SMTPManager.buffer and send only if it's
>>> full...
>>>
>>> 2) Sending the e-mail blocks the thread that logged the error. I don't
>> know
>>> how to "prove" this empirically, it's just a really clear subjective
>>> feeling: whenever an error gets logged, the whole application just lags
>> for
>>> the time it takes to send the mail.
>>>
>>> Can I provide you some help in pinpointing this problem?
>>>
>>>
>>> Overall: just ask if you need more information,
>>>
>>>
>>> Thanks!
>>>
>>>
>>> Matej
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>
>>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: Two problems with SMTPAppender
Posted by Matej Vitásek <ve...@gmail.com>.
Remko,
Thanks for the answer. After looking into the sources some more I found
this:
- SMTPAppender.append(), which seems to be the usual way of events being
logged to this appender, sends the mail directly.
- SMTPAppender.isFiltered(), which is an overriding of the usual logic
"filtered => do not log", instead collects the events in the cyclic buffer.
To be honest, I am quite confused with this behavior. Could you perhaps
shed some light on it?
Regarding buffering mails and having 1 error not sent for a long time: I
see your point, there can be perhaps a timeout setting.
Rationale: way too often, errors are clustered together. More often than
not, my app will send a barrage of error mails, and then be quiet for a
while. Even a timeout of 1 second would decrease the mail traffic
substantially, without losing any information.
What is your opinion of my second problem, the app being blocked while the
mail is being sent?
Thanks!
Matej
On Thu, May 9, 2013 at 2:48 PM, Remko Popma <re...@yahoo.com> wrote:
> Matej,
>
> The docs may not be clear on this, but i believe this buffer is
> essentially for multithreaded access.
>
> Every event will be stored in the buffer, and then trigger a send(). You
> are right that sending happens in the calling thread. You could consider
> wrapping the smtp appender in an async appender.
>
> When a send happens, it will grab all events currently in the buffer and
> send them in a single email.
>
> I believe this is correct behavior. Otherwise you may only have one ERROR
> and the email never gets sent because the appender is waiting for 9 more
> events...
>
> Best regards,
> Remko
>
> Sent from my iPhone
>
> On 2013/05/09, at 21:32, Matej Vitásek <ve...@gmail.com> wrote:
>
> > Hi all,
> >
> > I'd like to report 2 problems I am encountering using the SMTPAppender. I
> > am using it* to send me mails whenever an ERROR is logged in a web
> > application.
> >
> > 1) Buffer size is ignored. Excerpt from my log4j2.xml:
> > <SMTP name="Mail" suppressExceptions="false" subject="Error Log"
> > to="..." from="..." smtpHost="smtp.gmail.com"
> > smtpPort="465" *bufferSize="10"* smtpProtocol="smtps" smtpUsername="..."
> > smtpPassword="...">
> > </SMTP>
> >
> > You will notice that the buffer size is 10. I'd expect to be getting
> > e-mails with 10 errors aggregated, but every e-mail always contains only
> > one error.
> >
> > Looking into SMTPAppender.append() I see a call to manager.sendEvents()
> > which does not aggregate the message - it just sends it. To me it seems
> > that append() should write into SMTPManager.buffer and send only if it's
> > full...
> >
> > 2) Sending the e-mail blocks the thread that logged the error. I don't
> know
> > how to "prove" this empirically, it's just a really clear subjective
> > feeling: whenever an error gets logged, the whole application just lags
> for
> > the time it takes to send the mail.
> >
> > Can I provide you some help in pinpointing this problem?
> >
> >
> > Overall: just ask if you need more information,
> >
> >
> > Thanks!
> >
> >
> > Matej
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
>
Re: Two problems with SMTPAppender
Posted by Remko Popma <re...@yahoo.com>.
Matej,
The docs may not be clear on this, but i believe this buffer is essentially for multithreaded access.
Every event will be stored in the buffer, and then trigger a send(). You are right that sending happens in the calling thread. You could consider wrapping the smtp appender in an async appender.
When a send happens, it will grab all events currently in the buffer and send them in a single email.
I believe this is correct behavior. Otherwise you may only have one ERROR and the email never gets sent because the appender is waiting for 9 more events...
Best regards,
Remko
Sent from my iPhone
On 2013/05/09, at 21:32, Matej Vitásek <ve...@gmail.com> wrote:
> Hi all,
>
> I'd like to report 2 problems I am encountering using the SMTPAppender. I
> am using it* to send me mails whenever an ERROR is logged in a web
> application.
>
> 1) Buffer size is ignored. Excerpt from my log4j2.xml:
> <SMTP name="Mail" suppressExceptions="false" subject="Error Log"
> to="..." from="..." smtpHost="smtp.gmail.com"
> smtpPort="465" *bufferSize="10"* smtpProtocol="smtps" smtpUsername="..."
> smtpPassword="...">
> </SMTP>
>
> You will notice that the buffer size is 10. I'd expect to be getting
> e-mails with 10 errors aggregated, but every e-mail always contains only
> one error.
>
> Looking into SMTPAppender.append() I see a call to manager.sendEvents()
> which does not aggregate the message - it just sends it. To me it seems
> that append() should write into SMTPManager.buffer and send only if it's
> full...
>
> 2) Sending the e-mail blocks the thread that logged the error. I don't know
> how to "prove" this empirically, it's just a really clear subjective
> feeling: whenever an error gets logged, the whole application just lags for
> the time it takes to send the mail.
>
> Can I provide you some help in pinpointing this problem?
>
>
> Overall: just ask if you need more information,
>
>
> Thanks!
>
>
> Matej
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org