Some issues with logging and tests

[Benson Margulies <bi...@gmail.com>]

I've got a case, for which I'm about to file a JIRA, in which I think
that it's important that a particular situation leads to a log message
with some minimal content with a particular log level. Have we got any
tests for cases like this? I'm thinking about wiring up some sort of
test rig for intercepting log messages for the purpose.

Meanwhile, this particular case is perhaps worth a moment's discussion.

In JAX-RS, consider the following circumstance:

A resource accepts a parameter of bean type, and a mapper (in my case,
the Jackson json mapper) is responsible for mapping from the incoming
content to the bean. The incoming headers specify 'accept:
application/json', since that's what the function (normally) produces.

Now, someone debugging a python client sends a json blob with a
misspelled item in it. The mapper throws an exception.

WebApplicationExceptionMapper catches it and maps it to a 500,
accompanying the action with a log message at DEBUG.

The client gets a naked '500', no message anywhere. I suspect, but I'm
not sure, that the mapper would send back some backtracey verbiage if
the accept header were no so restrictive.

On the one hand, a WARN would be handy, as it's a pain to have to go
adjust the logging config just to see why the client isn't working. On
the other hand, a production application might get thousands of
malformed inputs a day, and might not want all this traffic in the
log.

Do we have a design principle (written down?) about how we decide what
should be logged non-DEBUG? Should errors resulting from ill-behaved
clients get that treatment? If not, I shouldn't write a JIRA or change
any code here.

Re: Some issues with logging and tests

[Sergey Beryozkin <sb...@gmail.com>]

Also updated the mapper to optionally report an error message (can be 
customized by extending the mapper) by setting an 'addMessageToResponse' 
property - which is ignored if the exception already contains Response 
with a non-null entity

Sergey

On 30/09/12 18:39, Sergey Beryozkin wrote:
> Hi
> On 30/09/12 18:03, Benson Margulies wrote:
>> On Sun, Sep 30, 2012 at 12:59 PM, Sergey
>> Beryozkin<sb...@gmail.com> wrote:
>>> On 30/09/12 14:33, Benson Margulies wrote:
>>>>
>>>> I've got a case, for which I'm about to file a JIRA, in which I think
>>>> that it's important that a particular situation leads to a log message
>>>> with some minimal content with a particular log level. Have we got any
>>>> tests for cases like this? I'm thinking about wiring up some sort of
>>>> test rig for intercepting log messages for the purpose.
>>>>
>>>> Meanwhile, this particular case is perhaps worth a moment's discussion.
>>>>
>>>> In JAX-RS, consider the following circumstance:
>>>>
>>>> A resource accepts a parameter of bean type, and a mapper (in my case,
>>>> the Jackson json mapper) is responsible for mapping from the incoming
>>>> content to the bean. The incoming headers specify 'accept:
>>>> application/json', since that's what the function (normally) produces.
>>>>
>>>> Now, someone debugging a python client sends a json blob with a
>>>> misspelled item in it. The mapper throws an exception.
>>>>
>>>> WebApplicationExceptionMapper catches it and maps it to a 500,
>>>> accompanying the action with a log message at DEBUG.
>>>>
>>>> The client gets a naked '500', no message anywhere. I suspect, but I'm
>>>> not sure, that the mapper would send back some backtracey verbiage if
>>>> the accept header were no so restrictive.
>>>>
>>>> On the one hand, a WARN would be handy, as it's a pain to have to go
>>>> adjust the logging config just to see why the client isn't working. On
>>>> the other hand, a production application might get thousands of
>>>> malformed inputs a day, and might not want all this traffic in the
>>>> log.
>>>>
>>>> Do we have a design principle (written down?) about how we decide what
>>>> should be logged non-DEBUG? Should errors resulting from ill-behaved
>>>> clients get that treatment? If not, I shouldn't write a JIRA or change
>>>> any code here.
>>>
>>> As I said in the previous message, it is to do with the
>>> over-optimization of
>>> WebApplicationExceptionMapper.
>>>
>>> By the way, I'm not sure I agree with the fix to CXF-4528.
>>> This is now getting complicated: one has to install a fault logger to
>>> get a
>>> stack trace, and, on top of that, the logging will happen twice, if
>>> property
>>> is set and FINE is active...
>>
>> That was the situation *before* I changed it. As of now, if there's no
>> fault logger, you have a stack trace if you make the call to turn on
>> the stack trace. If you *do* decide to put in a fault logger, you
>> decide whether to dump stack traces from it.
>>
>>>
>>> Let me propose something slightly different: if the fault logger is
>>> installed and it handled the exception: then do nothing else, the
>>> logger can
>>> log or ignore the error message, if not - do print the warn message
>>> because
>>> a number of times this issue has been raised - and this can be
>>> optimized if
>>> needed by turning 'printStackTrace' to false.
>>
>> That's what I did, except that I left it at 'FINE'. If I messed up the
>> logic let's look at the code together.
>>
> Sounds good, what do you think of r1392082 ?
> Basically, right now the logic is as follows:
>
> If the fault listener is available and has indicated it did handle the
> call - then do nothing else, otherwise - do either WARN (default) or
> FINE print stack trace message
>
> I guess there could be more variations (as to what to do when the fault
> listener has handled or has not handled the call - the logic can be
> improved), but I guess I'd like to make sure the user can get a print
> stack trace without having to install a listener...
>
> Thanks, Sergey


-- 
Sergey Beryozkin

Talend Community Coders
http://coders.talend.com/

Blog: http://sberyozkin.blogspot.com

Re: Some issues with logging and tests

[Sergey Beryozkin <sb...@gmail.com>]

Hi
On 30/09/12 18:03, Benson Margulies wrote:
> On Sun, Sep 30, 2012 at 12:59 PM, Sergey Beryozkin<sb...@gmail.com>  wrote:
>> On 30/09/12 14:33, Benson Margulies wrote:
>>>
>>> I've got a case, for which I'm about to file a JIRA, in which I think
>>> that it's important that a particular situation leads to a log message
>>> with some minimal content with a particular log level. Have we got any
>>> tests for cases like this? I'm thinking about wiring up some sort of
>>> test rig for intercepting log messages for the purpose.
>>>
>>> Meanwhile, this particular case is perhaps worth a moment's discussion.
>>>
>>> In JAX-RS, consider the following circumstance:
>>>
>>> A resource accepts a parameter of bean type, and a mapper (in my case,
>>> the Jackson json mapper) is responsible for mapping from the incoming
>>> content to the bean. The incoming headers specify 'accept:
>>> application/json', since that's what the function (normally) produces.
>>>
>>> Now, someone debugging a python client sends a json blob with a
>>> misspelled item in it. The mapper throws an exception.
>>>
>>> WebApplicationExceptionMapper catches it and maps it to a 500,
>>> accompanying the action with a log message at DEBUG.
>>>
>>> The client gets a naked '500', no message anywhere. I suspect, but I'm
>>> not sure, that the mapper would send back some backtracey verbiage if
>>> the accept header were no so restrictive.
>>>
>>> On the one hand, a WARN would be handy, as it's a pain to have to go
>>> adjust the logging config just to see why the client isn't working. On
>>> the other hand, a production application might get thousands of
>>> malformed inputs a day, and might not want all this traffic in the
>>> log.
>>>
>>> Do we have a design principle (written down?) about how we decide what
>>> should be logged non-DEBUG? Should errors resulting from ill-behaved
>>> clients get that treatment? If not, I shouldn't write a JIRA or change
>>> any code here.
>>
>> As I said in the previous message, it is to do with the over-optimization of
>> WebApplicationExceptionMapper.
>>
>> By the way, I'm not sure I agree with the fix to CXF-4528.
>> This is now getting complicated: one has to install a fault logger to get a
>> stack trace, and, on top of that, the logging will happen twice, if property
>> is set and FINE is active...
>
> That was the situation *before* I changed it. As of now, if there's no
> fault logger, you have a stack trace if you make the call to turn on
> the stack trace. If you *do* decide to put in a fault logger, you
> decide whether to dump stack traces from it.
>
>>
>> Let me propose something slightly different: if the fault logger is
>> installed and it handled the exception: then do nothing else, the logger can
>> log or ignore the error message, if not - do print the warn message because
>> a number of times this issue has been raised - and this can be optimized if
>> needed by turning 'printStackTrace' to false.
>
> That's what I did, except that I left it at 'FINE'. If I messed up the
> logic let's look at the code together.
>
Sounds good, what do you think of r1392082 ?
Basically, right now the logic is as follows:

If the fault listener is available and has indicated it did handle the 
call - then do nothing else, otherwise - do either WARN (default) or 
FINE print stack trace message

I guess there could be more variations (as to what to do when the fault 
listener has handled or has not handled the call - the logic can be 
improved), but I guess I'd like to make sure the user can get a print 
stack trace without having to install a listener...

Thanks, Sergey

Re: Some issues with logging and tests

[Benson Margulies <bi...@gmail.com>]

On Sun, Sep 30, 2012 at 12:59 PM, Sergey Beryozkin <sb...@gmail.com> wrote:
> On 30/09/12 14:33, Benson Margulies wrote:
>>
>> I've got a case, for which I'm about to file a JIRA, in which I think
>> that it's important that a particular situation leads to a log message
>> with some minimal content with a particular log level. Have we got any
>> tests for cases like this? I'm thinking about wiring up some sort of
>> test rig for intercepting log messages for the purpose.
>>
>> Meanwhile, this particular case is perhaps worth a moment's discussion.
>>
>> In JAX-RS, consider the following circumstance:
>>
>> A resource accepts a parameter of bean type, and a mapper (in my case,
>> the Jackson json mapper) is responsible for mapping from the incoming
>> content to the bean. The incoming headers specify 'accept:
>> application/json', since that's what the function (normally) produces.
>>
>> Now, someone debugging a python client sends a json blob with a
>> misspelled item in it. The mapper throws an exception.
>>
>> WebApplicationExceptionMapper catches it and maps it to a 500,
>> accompanying the action with a log message at DEBUG.
>>
>> The client gets a naked '500', no message anywhere. I suspect, but I'm
>> not sure, that the mapper would send back some backtracey verbiage if
>> the accept header were no so restrictive.
>>
>> On the one hand, a WARN would be handy, as it's a pain to have to go
>> adjust the logging config just to see why the client isn't working. On
>> the other hand, a production application might get thousands of
>> malformed inputs a day, and might not want all this traffic in the
>> log.
>>
>> Do we have a design principle (written down?) about how we decide what
>> should be logged non-DEBUG? Should errors resulting from ill-behaved
>> clients get that treatment? If not, I shouldn't write a JIRA or change
>> any code here.
>
> As I said in the previous message, it is to do with the over-optimization of
> WebApplicationExceptionMapper.
>
> By the way, I'm not sure I agree with the fix to CXF-4528.
> This is now getting complicated: one has to install a fault logger to get a
> stack trace, and, on top of that, the logging will happen twice, if property
> is set and FINE is active...

That was the situation *before* I changed it. As of now, if there's no
fault logger, you have a stack trace if you make the call to turn on
the stack trace. If you *do* decide to put in a fault logger, you
decide whether to dump stack traces from it.

>
> Let me propose something slightly different: if the fault logger is
> installed and it handled the exception: then do nothing else, the logger can
> log or ignore the error message, if not - do print the warn message because
> a number of times this issue has been raised - and this can be optimized if
> needed by turning 'printStackTrace' to false.

That's what I did, except that I left it at 'FINE'. If I messed up the
logic let's look at the code together.

>
> Sergey
>
>
>
>
> --
> Sergey Beryozkin
>
> Talend Community Coders
> http://coders.talend.com/
>
> Blog: http://sberyozkin.blogspot.com

Re: Some issues with logging and tests

[Sergey Beryozkin <sb...@gmail.com>]

On 30/09/12 14:33, Benson Margulies wrote:
> I've got a case, for which I'm about to file a JIRA, in which I think
> that it's important that a particular situation leads to a log message
> with some minimal content with a particular log level. Have we got any
> tests for cases like this? I'm thinking about wiring up some sort of
> test rig for intercepting log messages for the purpose.
>
> Meanwhile, this particular case is perhaps worth a moment's discussion.
>
> In JAX-RS, consider the following circumstance:
>
> A resource accepts a parameter of bean type, and a mapper (in my case,
> the Jackson json mapper) is responsible for mapping from the incoming
> content to the bean. The incoming headers specify 'accept:
> application/json', since that's what the function (normally) produces.
>
> Now, someone debugging a python client sends a json blob with a
> misspelled item in it. The mapper throws an exception.
>
> WebApplicationExceptionMapper catches it and maps it to a 500,
> accompanying the action with a log message at DEBUG.
>
> The client gets a naked '500', no message anywhere. I suspect, but I'm
> not sure, that the mapper would send back some backtracey verbiage if
> the accept header were no so restrictive.
>
> On the one hand, a WARN would be handy, as it's a pain to have to go
> adjust the logging config just to see why the client isn't working. On
> the other hand, a production application might get thousands of
> malformed inputs a day, and might not want all this traffic in the
> log.
>
> Do we have a design principle (written down?) about how we decide what
> should be logged non-DEBUG? Should errors resulting from ill-behaved
> clients get that treatment? If not, I shouldn't write a JIRA or change
> any code here.
As I said in the previous message, it is to do with the 
over-optimization of WebApplicationExceptionMapper.

By the way, I'm not sure I agree with the fix to CXF-4528.
This is now getting complicated: one has to install a fault logger to 
get a stack trace, and, on top of that, the logging will happen twice, 
if property is set and FINE is active...

Let me propose something slightly different: if the fault logger is 
installed and it handled the exception: then do nothing else, the logger 
can log or ignore the error message, if not - do print the warn message 
because a number of times this issue has been raised - and this can be 
optimized if needed by turning 'printStackTrace' to false.

Sergey




-- 
Sergey Beryozkin

Talend Community Coders
http://coders.talend.com/

Blog: http://sberyozkin.blogspot.com