Bug 63287

Summary: Inconsistent log level practices in Catalina component
Product: Tomcat 9 Reporter: AnhT <anuhan>
Component: CatalinaAssignee: Tomcat Developers Mailing List <dev>
Status: RESOLVED FIXED    
Severity: enhancement    
Priority: P2    
Version: 9.0.x   
Target Milestone: -----   
Hardware: All   
OS: All   

Description AnhT 2019-03-26 07:32:51 UTC
Inconsistent log level practices in similar code snippets as well as the modification suggestion are shown below.

***************** Report1 *********************************
the problematic snippet:
============ JAASMemoryLoginModule.java ===================
file path: tomcat\java\org\apache\catalina\realm\JAASMemoryLoginModule.java
logging statement line: 403
modification suggestion: change log level to ERROR
399         try {
400             digester.push(this);
401             digester.parse(file);
402         } catch (Exception e) {
403             log.warn(sm.getString("jaasMemoryLoginModule.parseError", 
                file.getAbsolutePath()), e);
404         } finally {
405             digester.reset();
406         }

the similar snippet:
============ MbeansDescriptorsDigesterSource.java =========
filepath:tomcat\java\org\apache\tomcat\util\modeler\modules\MbeansDescriptorsDigesterSource.java
logging statement line:171
166             try {
167                 // Push our registry object onto the stack
168                 digester.push(loadedMbeans);
169                 digester.parse(stream);
170             } catch (Exception e) {
171                 log.error(sm.getString("modules.digesterParseError"), e);
172                 throw e;
173             } finally {
174                 digester.reset();
175             }

***************** Report2 *********************************
the problematic snippet:
============ AccessLogValve.java ===================
file path: tomcat\java\org\apache\catalina\valves\AccessLogValve.java
logging statement line: 642
modification suggestion: change log level to WARN
639             try {
640                 charset = B2CConverter.getCharset(encoding);
641             } catch (UnsupportedEncodingException ex) {
642                 log.error(sm.getString(
643                         "accessLogValve.unsupportedEncoding", encoding), ex);
644             }

the similar snippets:
============ Response.java =========================
file path: tomcat\java\org\apache\coyote\Response.java
logging statement line: 550
547                 try {
548                     charset = B2CConverter.getCharset(charsetValue);
549                 } catch (UnsupportedEncodingException e) {
550                     log.warn(sm.getString("response.encoding.invalid", charsetValue), e);
551                 }

============ MessageDigestCredentialHandler.java ===
file path: tomcat\java\org\apache\catalina\realm\MessageDigestCredentialHandler.java
logging statement line: 75
72             try {
73                 this.encoding = B2CConverter.getCharset(encodingName);
74             } catch (UnsupportedEncodingException e) {
75                 log.warn(sm.getString("mdCredentialHandler.unknownEncoding",
76                         encodingName, encoding.name()));
77             }

============ Connector.java ========================
file path: tomcat\java\org\apache\catalina\connector\Connector.java
logging statement line: 752
749         try {
750             uriCharset = B2CConverter.getCharset(URIEncoding);
751         } catch (UnsupportedEncodingException e) {
752             log.warn(sm.getString("coyoteConnector.invalidEncoding",
753                     URIEncoding, uriCharset.name()), e);
754         }

***************** Report3 *********************************
the problematic snippet:
============ StaticMembershipProvider.java =========
file path: tomcat\java\org\apache\catalina\tribes\membership\StaticMembershipProvider.java
logging statement line: 402
modification suggestion: change log level to ERROR
397                 try {
398                     sleep(pingInterval);
399                     ping();
400                 }catch (InterruptedException ix) {
401                 }catch (Exception x) {
402                     log.warn(sm.getString("staticMembershipProvider.pingThread.failed"),x);
403                 }


the similar snippet:
============ StaticMembershipProvider.java =========
file path: tomcat\java\org\apache\catalina\tribes\membership\StaticMembershipProvider.java
logging statement line:274
271         try {
272             if (!useThread) ping();
273         } catch (ChannelException e) {
274             log.error(sm.getString("staticMembershipProvider.heartbeat.failed"), e);
275         }
Comment 1 Mark Thomas 2019-03-28 22:44:00 UTC
Thanks for the report.

Reviewing the individual reports I think there is a little to much focus on similarity of code and not enough focus on similarity of function. To put it another way, an invalid charset may be a minor issue when provided as part of a user request but a significant issue if a security realm is configured to digest passwords using an invalid encoding.

For report 1, a better comparison would be how the MemoryUserDatabase handles a missing/invalid tomcat-users.xml file. Also, there are other error conditions earlier in JAASMemoryLoginModule that should be treated in a consistent manner.

For report 2, an argument could be made that AccessLogValve should use WARN but it isn't a very strong argument. For Response, an invalid encoding may not be an error so WARN seems right. I think there is a case for making MessageDigestCredentialHandler and Connector ERROR.

For report 3, I agree they should be the same buy I'd switch to WARN since cluster nodes going down isn't unexpected.

Fixed in master for 9.0.18 onwards.
Comment 2 AnhT 2019-03-29 01:25:58 UTC
Thank you very much Mark for your feedback and insightful suggestion that have helped to refine my work.