Bug 63249 - Inconsistent log level practices
Summary: Inconsistent log level practices
Status: RESOLVED FIXED
Alias: None
Product: Tomcat 9
Classification: Unclassified
Component: Catalina (show other bugs)
Version: 9.0.16
Hardware: PC All
: P2 enhancement (vote)
Target Milestone: -----
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2019-03-09 04:06 UTC by AnhT
Modified: 2019-03-14 12:31 UTC (History)
1 user (show)



Attachments
Patch fille (922 bytes, patch)
2019-03-09 04:24 UTC, AnhT
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description AnhT 2019-03-09 04:06:54 UTC
There are inconsistent log level practices in similiar situations.
(1)file path:apache-tomcat-9.0.16-src\java\org\apache\catalina\util\LifecycleMBeanBase.java
//log level:warn
        try {
            on = new ObjectName(name.toString());

            Registry.getRegistry(null, null).registerComponent(obj, on, null);
        } catch (MalformedObjectNameException e) {
            log.warn(sm.getString("lifecycleMBeanBase.registerFail", obj, name),
                    e);
        } catch (Exception e) {
            log.warn(sm.getString("lifecycleMBeanBase.registerFail", obj, name),
                    e);
        }
(2)file path:apache-tomcat-9.0.16-src\java\org\apache\catalina\core\ApplicationFilterConfig.java
//log level:info
        try {
            oname = new ObjectName(onameStr);
            Registry.getRegistry(null, null).registerComponent(this, oname,
                    null);
        } catch (Exception ex) {
            log.info(sm.getString("applicationFilterConfig.jmxRegisterFail",
                    getFilterClass(), getFilterName()), ex);
        }
(3)file path:apache-tomcat-9.0.16-src\java\org\apache\catalina\core\StandardWrapper.java
//log level:info
            try {
                jspMonitorON = new ObjectName(oname.toString());
                Registry.getRegistry(null, null)
                    .registerComponent(instance, jspMonitorON, null);
            } catch (Exception ex) {
                log.info(sm.getString("standardWrapper.jspMonitorError", instance));
            }

I think the log level should be consistent in above contexts, so the log level of first example more likely to be assigned INFO.
Comment 1 AnhT 2019-03-09 04:24:06 UTC
Created attachment 36480 [details]
Patch fille

Modify the log levels to INFO in file apache-tomcat-9.0.16-src\java\org\apache\catalina\util\LifecycleMBeanBase.java.
Comment 2 Mark Thomas 2019-03-13 18:51:24 UTC
Nice find.


I did a search of the code base. It wasn't perfect but I found 2 instances of INFO, 7 of WARN and 8 of ERROR.

Generally, the ERROR logs were related to a more general failure to start or stop a component.

JMX registration should not fail and breakage is likely if it does so WARN seems more appropriate here.

I'll get this fixed shortly.
Comment 3 AnhT 2019-03-14 07:51:31 UTC
Hi, Mark Thomas. Thank you very much for your prompt response. 
There are other 6 inconsistent logging practices shown below, and I think the ERROR level is more appropriate to them.
============StandardService.java===================
full path: tomcat\java\org\apache\catalina\core\StandardService.java
log line num: 137; 144; 149; 155

132         if (getState().isAvailable()) {
133             if (this.engine != null) {
134                 try {
135                     this.engine.start();
136                 } catch (LifecycleException e) {
137                     log.warn(sm.getString("standardService.engine.startFailed"), e);
138                 }
139             }
140             // Restart MapperListener to pick up new engine.
141             try {
142                 mapperListener.stop();
143             } catch (LifecycleException e) {
144              log.warn(sm.getString("standardService.mapperListener.stopFailed"), e);
145             }
146             try {
147                 mapperListener.start();
148             } catch (LifecycleException e) {
149             log.warn(sm.getString("standardService.mapperListener.startFailed"), e);
150             }
151             if (oldEngine != null) {
152                 try {
153                     oldEngine.stop();
154                 } catch (LifecycleException e) {
155                     log.warn(sm.getString("standardService.engine.stopFailed"), e);
156                 }
157             }
158         }

============HostConfig.java===================
full path: tomcat\java\org\apache\catalina\startup\HostConfig.java
log line num: 1414

1396         Context context = (Context) host.findChild(app.name);
1397         if (context.getState().isAvailable()) {
1398             if (fileToRemove != null && newDocBase != null) {
1399                 context.addLifecycleListener(
1400                         new ExpandedDirectoryRemovalListener(fileToRemove, newDocBase));
1401             }
1402             // Reload catches and logs exceptions
1403             context.reload();
1404         } else {
1405             // If the context was not started (for example an error
1406             // in web.xml) we'll still get to try to start
1407             if (fileToRemove != null && newDocBase != null) {
1408                 ExpandWar.delete(fileToRemove);
1409                 context.setDocBase(newDocBase);
1410             }
1411             try {
1412                 context.start();
1413             } catch (Exception e) {
1414                 log.warn(sm.getString
1415                          ("hostConfig.context.restart", app.name), e);
1416             }
1417         }

=============LifecycleBase.java=======================
full path: tomcat\java\org\apache\catalina\util\LifecycleBase.java
log line num: 296

290         if (LifecycleState.FAILED.equals(state)) {
291             try {
292                 // Triggers clean-up
293                 stop();
294             } catch (LifecycleException e) {
295                 // Just log. Still want to destroy.
296                 log.warn(sm.getString(
297                         "lifecycleBase.destroyStopFail", toString()), e);
298             }
299         }
Comment 4 AnhT 2019-03-14 08:40:44 UTC
Hi, Mark Thomas. Thank you very much for your prompt response. 
There are other inconsistent logging practices shown below, and I think the ERROR level is more appropriate to following 6 log statements.
============StandardService.java===================
file path: apache-tomcat-9.0.16-src\java\org\apache\catalina\core\StandardService.java
log line num: 137; 144; 149; 155

132         if (getState().isAvailable()) {
133             if (this.engine != null) {
134                 try {
135                     this.engine.start();
136                 } catch (LifecycleException e) {
137                     log.warn(sm.getString("standardService.engine.startFailed"), e);
138                 }
139             }
140             // Restart MapperListener to pick up new engine.
141             try {
142                 mapperListener.stop();
143             } catch (LifecycleException e) {
144              log.warn(sm.getString("standardService.mapperListener.stopFailed"), e);
145             }
146             try {
147                 mapperListener.start();
148             } catch (LifecycleException e) {
149             log.warn(sm.getString("standardService.mapperListener.startFailed"), e);
150             }
151             if (oldEngine != null) {
152                 try {
153                     oldEngine.stop();
154                 } catch (LifecycleException e) {
155                     log.warn(sm.getString("standardService.engine.stopFailed"), e);
156                 }
157             }
158         }

============HostConfig.java===================
file path: apache-tomcat-9.0.16-src\java\org\apache\catalina\startup\HostConfig.java
log line num: 1414

1411             try {
1412                 context.start();
1413             } catch (Exception e) {
1414                 log.warn(sm.getString
1415                          ("hostConfig.context.restart", app.name), e);
1416             }

=============LifecycleBase.java=======================
file path: apache-tomcat-9.0.16-src\java\org\apache\catalina\util\LifecycleBase.java
log line num: 296

290         if (LifecycleState.FAILED.equals(state)) {
291             try {
292                 // Triggers clean-up
293                 stop();
294             } catch (LifecycleException e) {
295                 // Just log. Still want to destroy.
296                 log.warn(sm.getString(
297                         "lifecycleBase.destroyStopFail", toString()), e);
298             }
299         }


***Following 10 logging statements are assigned to ERROR level in code*****
=============StandardService.java=======================
file path: apache-tomcat-9.0.16-srct\java\org\apache\catalina\core\StandardService.java
log line num: 293; 348
290                 try {
291                     connectors[j].stop();
292                 } catch (LifecycleException e) {
293                     log.error(sm.getString(
294                             "standardService.connector.stopFailed",
295                             connectors[j]), e);
296                 }

345                     try {
346                         ex.start();
347                     } catch (LifecycleException x) {
348                         log.error(sm.getString("standardService.executor.start"), x);
349                     }

=============StandardPipeline.java====================
file path: apache-tomcat-9.0.16-src\java\org\apache\catalina\core\StandardPipeline.java
log line num: 293; 345
290             try {
291                 ((Lifecycle) valve).start();
292             } catch (LifecycleException e) {
293                 log.error(sm.getString("standardPipeline.basic.start"), e);
294                 return;
295             }

342                 try {
343                     ((Lifecycle) valve).start();
344                 } catch (LifecycleException e) {
345                     log.error(sm.getString("standardPipeline.valve.start"), e);
346                 }
=============CombinedRealm.java======================
file path:apache-tomcat-9.0.16-src\java\org\apache\catalina\realm\CombinedRealm.java
log line num:249
244                 try {
245                     ((Lifecycle) realm).start();
246                 } catch (LifecycleException e) {
247                     // If realm doesn't start can't authenticate against it
248                     iter.remove();
249                     log.error(sm.getString("combinedRealm.realmStartFail",
250                             realm.getClass().getName()), e);
251                 }


=============StandardContext.java======================
file path: apache-tomcat-9.0.16-src\java\org\apache\catalina\core\StandardContext.java
log line num: 1844; 1899; 3750
1841                 try {
1842                     ((Lifecycle) oldLoader).stop();
1843                 } catch (LifecycleException e) {
1844                     log.error(sm.getString("standardContext.setLoader.stop"), e);
1845                 }


1895                 try {
1896                     ((Lifecycle) oldManager).stop();
1897                     ((Lifecycle) oldManager).destroy();
1898                 } catch (LifecycleException e) {
1899                     log.error(sm.getString("standardContext.setManager.stop"), e);
1900                 }


3747         try {
3748             stop();
3749         } catch (LifecycleException e) {
3750             log.error(
3751                 sm.getString("standardContext.stoppingContext", getName()), e);
3752         }

=============ContainerBase.java========================
file path:apache-tomcat-9.0.16-src\java\org\apache\catalina\core\ContainerBase.java
log line num: 437; 650
 434                 try {
 435                     ((Lifecycle) cluster).start();
 436                 } catch (LifecycleException e) {
 437                     log.error(sm.getString("containerBase.cluster.start"), e);
 438                 }

 647                 try {
 648                     ((Lifecycle) realm).start();
 649                 } catch (LifecycleException e) {
 650                     log.error(sm.getString("containerBase.realm.start"), e);
 651                 }
Comment 5 AnhT 2019-03-14 08:48:20 UTC
(In reply to AnhT from comment #3)
> Hi, Mark Thomas. Thank you very much for your prompt response. 
> There are other 6 inconsistent logging practices shown below, and I think
> the ERROR level is more appropriate to them.
> ============StandardService.java===================
> full path: tomcat\java\org\apache\catalina\core\StandardService.java
> log line num: 137; 144; 149; 155
> 
> 132         if (getState().isAvailable()) {
> 133             if (this.engine != null) {
> 134                 try {
> 135                     this.engine.start();
> 136                 } catch (LifecycleException e) {
> 137                    
> log.warn(sm.getString("standardService.engine.startFailed"), e);
> 138                 }
> 139             }
> 140             // Restart MapperListener to pick up new engine.
> 141             try {
> 142                 mapperListener.stop();
> 143             } catch (LifecycleException e) {
> 144             
> log.warn(sm.getString("standardService.mapperListener.stopFailed"), e);
> 145             }
> 146             try {
> 147                 mapperListener.start();
> 148             } catch (LifecycleException e) {
> 149            
> log.warn(sm.getString("standardService.mapperListener.startFailed"), e);
> 150             }
> 151             if (oldEngine != null) {
> 152                 try {
> 153                     oldEngine.stop();
> 154                 } catch (LifecycleException e) {
> 155                    
> log.warn(sm.getString("standardService.engine.stopFailed"), e);
> 156                 }
> 157             }
> 158         }
> 
> ============HostConfig.java===================
> full path: tomcat\java\org\apache\catalina\startup\HostConfig.java
> log line num: 1414
> 
> 1396         Context context = (Context) host.findChild(app.name);
> 1397         if (context.getState().isAvailable()) {
> 1398             if (fileToRemove != null && newDocBase != null) {
> 1399                 context.addLifecycleListener(
> 1400                         new
> ExpandedDirectoryRemovalListener(fileToRemove, newDocBase));
> 1401             }
> 1402             // Reload catches and logs exceptions
> 1403             context.reload();
> 1404         } else {
> 1405             // If the context was not started (for example an error
> 1406             // in web.xml) we'll still get to try to start
> 1407             if (fileToRemove != null && newDocBase != null) {
> 1408                 ExpandWar.delete(fileToRemove);
> 1409                 context.setDocBase(newDocBase);
> 1410             }
> 1411             try {
> 1412                 context.start();
> 1413             } catch (Exception e) {
> 1414                 log.warn(sm.getString
> 1415                          ("hostConfig.context.restart", app.name), e);
> 1416             }
> 1417         }
> 
> =============LifecycleBase.java=======================
> full path: tomcat\java\org\apache\catalina\util\LifecycleBase.java
> log line num: 296
> 
> 290         if (LifecycleState.FAILED.equals(state)) {
> 291             try {
> 292                 // Triggers clean-up
> 293                 stop();
> 294             } catch (LifecycleException e) {
> 295                 // Just log. Still want to destroy.
> 296                 log.warn(sm.getString(
> 297                         "lifecycleBase.destroyStopFail", toString()), e);
> 298             }
> 299         }

I present the details in Comment 4. Please ignore this comment.
Comment 6 Mark Thomas 2019-03-14 11:13:47 UTC
The log levels for the JMX (de-)registration messages have been addressed in:
- master for 9.0.18 onwards
- 8.5.x for 8.5.40 onwards
- 7.0.x for 7.0.94 onwards

I'll look at the Lifecycle issues next but please can I ask that you open a new bug report if you find any further issues. Separate bug reports makes it easier to track what has been fixed and what hasn't.
Comment 7 AnhT 2019-03-14 11:39:07 UTC
(In reply to Mark Thomas from comment #6)
> The log levels for the JMX (de-)registration messages have been addressed in:
> - master for 9.0.18 onwards
> - 8.5.x for 8.5.40 onwards
> - 7.0.x for 7.0.94 onwards
> 
> I'll look at the Lifecycle issues next but please can I ask that you open a
> new bug report if you find any further issues. Separate bug reports makes it
> easier to track what has been fixed and what hasn't.

OK, I will report the bugs in new page, thanks for your response.
Comment 8 Remy Maucherat 2019-03-14 11:46:18 UTC
We should probably recommend using PRs for multiple simple changes like this one.
Comment 9 Mark Thomas 2019-03-14 12:31:40 UTC
Fixed in:
- master for 9.0.18 onwards
- 8.5.x for 8.5.40 onwards
- 7.0.x for 7.0.94 onwards

The GH Issues / GH PR/ BZ discussion is probably one for the dev@ list