Bug 56401

Fixed in 8.0.x and will be included in 8.0.13 onwards.

Several comments, from testing this and adding i18n in r1623804

1. It is good that this does not affect embedded Tomcat.
There are no changes in the information logged by unit tests.

2. The Catalina.logInfo() method is called from Catalina class constructor. As such, it performs logging on shutdown.bat.
I think it should not perform logging on shutdown. As such, I am REOPENing this.

An alternative implementation could be a <Listener> in server.xml that prints such information.

Additional concern:
3. It may be better to log all information in one single log.info() statement. E.g. "Initializing\n {0}\n {1}\n {2} ...".  The current log format implicitly relies on use of org.apache.juli.OneLineFormatter.

If you backport it to Tomcat 7 that uses SimpleFormatter, or if you run Tomcat 8 from within Eclipse IDE (that does not have logging configured by default == uses JRE default configuration == uses SimpleFormatter), it looks rather odd.


Reverted the code in r1627247 due to item #2 that I raised in Comment #2.

Re-impemented as a LifecycleListener

Re: r1627296

Could the logging be moved from constructor to Lifecycle.BEFORE_INIT_EVENT, like activities performed by AprLifecycleListener?


Reason: Doing logging in VersionLoggerListener constructor interferes with storeconfig feature. IIRC, it instantiates classes to look for their default properties to omit writing them out.

Steps to reproduce with Tomcat 8.0.14 release candidate and JDK 7u67:

1. Add the following listener to conf/server.xml
  <Listener className="org.apache.catalina.storeconfig.StoreConfigLifecycleListener"/>

2. Start Tomcat

3. Connect with jconsole, open mbean Catalina/StoreConfig and invoke "storeConfig()" operation.

4. The following messages are logged for this operation:

[[[
25-Sep-2014 16:38:24.694 INFO [RMI TCP Connection(1)-<IPADDRESS>] org.apache.catalina.startup.VersionLoggerListener.log Server version: Apache Tomcat/8.0.14
25-Sep-2014 16:38:24.697 INFO [RMI TCP Connection(1)-<IPADDRESS>] org.apache.catalina.startup.VersionLoggerListener.log Server built:   Sep 24 2014 09:01:51
25-Sep-2014 16:38:24.699 INFO [RMI TCP Connection(1)-<IPADDRESS>] org.apache.catalina.startup.VersionLoggerListener.log Server number:  8.0.14.0
25-Sep-2014 16:38:24.700 INFO [RMI TCP Connection(1)-<IPADDRESS>] org.apache.catalina.startup.VersionLoggerListener.log OS Name:        Windows 7
25-Sep-2014 16:38:24.702 INFO [RMI TCP Connection(1)-<IPADDRESS>] org.apache.catalina.startup.VersionLoggerListener.log OS Version:     6.1
25-Sep-2014 16:38:24.703 INFO [RMI TCP Connection(1)-<IPADDRESS>] org.apache.catalina.startup.VersionLoggerListener.log Architecture:   x86
25-Sep-2014 16:38:24.704 INFO [RMI TCP Connection(1)-<IPADDRESS>] org.apache.catalina.startup.VersionLoggerListener.log JVM Version:    1.7.0_67-b01
25-Sep-2014 16:38:24.705 INFO [RMI TCP Connection(1)-<IPADDRESS>] org.apache.catalina.startup.VersionLoggerListener.log JVM Vendor:     Oracle Corporation
25-Sep-2014 16:38:24.796 INFO [RMI TCP Connection(1)-<IPADDRESS>] org.apache.catalina.storeconfig.StandardContextSF.storeWithBackup Store Context  separate with backup (at file <CATALINA_BASE>\conf\Catalina\localhost\ROOT.xml.2014-09-25.16-38-24 )
25-Sep-2014 16:38:24.829 INFO [RMI TCP Connection(1)-<IPADDRESS>] org.apache.catalina.storeconfig.StandardContextSF.storeWithBackup Store Context /manager separate with backup (at file <CATALINA_BASE>\webapps\manager\META-INF\context.xml.2014-09-25.16-38-24 )
25-Sep-2014 16:38:24.847 INFO [RMI TCP Connection(1)-<IPADDRESS>] org.apache.catalina.storeconfig.StandardContextSF.storeWithBackup Store Context /docs separate with backup (at file <CATALINA_BASE>\conf\Catalina\localhost\docs.xml.2014-09-25.16-38-24 )
25-Sep-2014 16:38:24.865 INFO [RMI TCP Connection(1)-<IPADDRESS>] org.apache.catalina.storeconfig.StandardContextSF.storeWithBackup Store Context /examples separate with backup (at file <CATALINA_BASE>\conf\Catalina\localhost\examples.xml.2014-09-25.16-38-24 )
25-Sep-2014 16:38:24.889 INFO [RMI TCP Connection(1)-<IPADDRESS>] org.apache.catalina.storeconfig.StandardContextSF.storeWithBackup Store Context /host-manager separate with backup (at file <CATALINA_BASE>\webapps\host-manager\META-INF\context.xml.2014-09-25.16-38-24 )
]]]

(In reply to Konstantin Kolinko from comment #5)
> Re: r1627296
> 
> Could the logging be moved from constructor to Lifecycle.BEFORE_INIT_EVENT,
> like activities performed by AprLifecycleListener?

They could, but then you have the problem that the AprLifecycleListener triggers logging in its constructor and I think that version info logging should appear before any other logging.

I took a quick look at refactoring the AprLifecycleListener but that is tied up with the Connector constructors and would be hard to untangle.

I'm happy to look at this some more but if anyone has a bright idea on how to solve this...

> I took a quick look at refactoring the AprLifecycleListener but that
> is tied up with the Connector constructors and would be hard to untangle.

Ack. Agreed.


For a record, the call chain to AprLifecycleListener.init() is the following.

[[[
at org.apache.catalina.core.AprLifecycleListener.init(AprLifecycleListener.java:181)
at org.apache.catalina.core.AprLifecycleListener.isAprAvailable(AprLifecycleListener.java:96)
at org.apache.catalina.connector.Connector.setProtocol(Connector.java:564)
at org.apache.catalina.connector.Connector.<init>(Connector.java:66)
at org.apache.catalina.startup.ConnectorCreateRule.begin(ConnectorCreateRule.java:62)
]]]

When parsing server.xml one needs to set properties on a Connector. Majority of those properties are propagated further to a ProtocolHandler class. Configuring a ProtocolHandler by default auto-selects between APR and non-APR implementation. That auto-selection relies on response from AprLifecycleListener.isAprAvailable(). Thus init() method is triggered.

So I agree that it is difficult to untangle it.

The best I can come up with is to write all the info logging during AprLifecycleListener.init() to a buffer and then write that out during Lifecycle.BEFORE_INIT_EVENT. Then move the VersionLogging messages to Lifecycle.BEFORE_INIT_EVENT as well.

Errors and warnings would still appear before the version information but I could live with that.

I'll take a look at at patch to do this shortly.

Imporved fix applied to 8.0.x for 8.0.15 onwards.

This is back-ported in 7.0.x and will be available in 7.0.57 onwards.