Re: Some issues with logging and tests
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 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
Hi On 30/09/12 18:03, Benson Margulies wrote: On Sun, Sep 30, 2012 at 12:59 PM, Sergey Beryozkin 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
On Sun, Sep 30, 2012 at 12:59 PM, Sergey Beryozkin 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
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