Tomcat7 logging hell - why two different formats coming out?

Question

My logging.properties in Eclipse looked like this when I initially posted this question:

handlers = java.util.logging.ConsoleHandler

org.apache.catalina.core=OFF

java.util.logging.ConsoleHandler.level = FINE
java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter
java.util.logging.SimpleFormatter.format=JUL %4$s: %2$s%n%4$s: %5$s%n

I am also encountering the same issue on a Linux server with this configuration:

handlers = 2localhost.org.apache.juli.FileHandler, org.apache.juli.FileHandler

.handlers = org.apache.juli.FileHandler

2localhost.org.apache.juli.FileHandler.level = INFO
2localhost.org.apache.juli.FileHandler.directory = ${catalina.base}/logs
2localhost.org.apache.juli.FileHandler.prefix = localhost.

org.apache.juli.FileHandler.level = ALL
org.apache.juli.FileHandler.formatter = java.util.logging.SimpleFormatter
org.apache.juli.FileHandler.directory = ${catalina.base}/logs
java.util.logging.SimpleFormatter.format=tomcat: %4$s: %2$s%n%4$s: %5$s%n

org.apache.catalina.handlers = org.apache.juli.FileHandler
org.apache.catalina.startup.level = SEVERE
org.apache.catalina.session.ManagerBase.level = SEVERE
org.apache.catalina.core.AprLifecycleListener.level=SEVERE
org.apache.catalina.connector.level = SEVERE
org.apache.coyote.level=SEVERE

org.apache.catalina.level=ALL
org.apache.catalina.startup.HostConfig.level = SEVERE
org.apache.catalina.loader.WebappClassLoader.level = SEVERE
org.apache.catalina.session.ManagerBase.level = INFO

# ServletContext logger
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].level = ALL
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].handlers = 2localhost.org.apache.juli.FileHandler
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].formatter = java.util.logging.SimpleFormatter
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].format=servlet: %4$s: %2$s%n%4$s: %5$s%n

Why then does my console log in Eclipse look like this?

JUL INFO: org.apache.catalina.core.AprLifecycleListener init
INFO: The APR based Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: C:\Program Files\Java\jdk1.8.0_05\bin;C:\Windows\Sun\Java\bin;C:\Windows\system32;C:\Windows;C:\Program Files\Common Files\Microsoft Shared\Windows Live;C:\Program Files (x86)\Common Files\Microsoft Shared\Windows Live;c:\Program Files (x86)\Intel\iCLS Client\;c:\Program Files\Intel\iCLS Client\;C:\Program Files (x86)\NVIDIA Corporation\PhysX\Common;C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\Windows\System32\WindowsPowerShell\v1.0\;C:\Program Files\Intel\Intel(R) Management Engine Components\DAL;C:\Program Files\Intel\Intel(R) Management Engine Components\IPT;C:\Program Files (x86)\Intel\Intel(R) Management Engine Components\DAL;C:\Program Files (x86)\Intel\Intel(R) Management Engine Components\IPT;C:\Program Files\TortoiseSVN\bin;C:\Program Files (x86)\Bitvise SSH Client;C:\Program Files (x86)\MySQL\MySQL Utilities 1.4.3\;C:\Program Files (x86)\MySQL\MySQL Utilities 1.4.3\Doctrine extensions for PHP\;C:\Program Files (x86)\Windows Live\Shared;C:\Program Files\TortoiseGit\bin;C:\Program Files (x86)\Git\cmd;C:\Program Files\Microsoft SQL Server\110\Tools\Binn\;C:\Program Files\Microsoft\Web Platform Installer\;C:\Program Files (x86)\Microsoft ASP.NET\ASP.NET Web Pages\v1.0\;C:\Program Files (x86)\Windows Kits\8.0\Windows Performance Toolkit\;C:\Program Files (x86)\BaseX\bin;C:\Program Files (x86)\WinMerge;C:\Program Files (x86)\Skype\Phone\;.
JUL WARNING: org.apache.tomcat.util.digester.SetPropertiesRule begin
WARNING: [SetPropertiesRule]{Server/Service/Engine/Host/Context} Setting property 'source' to 'org.eclipse.jst.jee.server:ctc_web_front_ui' did not find a matching property.
JUL INFO: org.apache.coyote.AbstractProtocol init
INFO: Initializing ProtocolHandler ["http-bio-8080"]
JUL INFO: org.apache.coyote.AbstractProtocol init
INFO: Initializing ProtocolHandler ["ajp-bio-8009"]
JUL INFO: org.apache.catalina.startup.Catalina load
INFO: Initialization processed in 359 ms
JUL INFO: org.apache.catalina.core.StandardService startInternal
INFO: Starting service Catalina
JUL INFO: org.apache.catalina.core.StandardEngine startInternal
INFO: Starting Servlet Engine: Apache Tomcat/7.0.47
JUL INFO: org.apache.catalina.core.ApplicationContext log
INFO: No Spring WebApplicationInitializer types detected on classpath
JUL INFO: org.apache.catalina.core.ApplicationContext log
INFO: Initializing Spring FrameworkServlet 'servletSpringDispatcher'
JUL INFO: org.springframework.web.servlet.FrameworkServlet initServletBean
INFO: FrameworkServlet 'servletSpringDispatcher': initialization started

Where are the bare INFO messages coming from?

And why are catalina.core messages still showing up even though I set them to OFF?

On the Linux server the JULI log looks like this:

tomcat: FINE: org.apache.catalina.core.ContainerBase addChildInternal
FINE: Add child StandardHost[localhost] StandardEngine[Catalina]
tomcat: FINE: org.apache.catalina.util.LifecycleBase setStateInternal
FINE: Setting state for [StandardServer[8005]] to [INITIALIZING]
tomcat: FINE: org.apache.catalina.util.LifecycleBase setStateInternal
FINE: Setting state for [org.apache.catalina.deploy.NamingResources@13fee20c] to [INITIALIZING]
tomcat: FINE: org.apache.catalina.util.LifecycleBase setStateInternal
FINE: Setting state for [org.apache.catalina.deploy.NamingResources@13fee20c] to [INITIALIZED]
tomcat: FINE: org.apache.catalina.util.LifecycleBase setStateInternal
FINE: Setting state for [StandardService[Catalina]] to [INITIALIZING]
tomcat: FINE: org.apache.catalina.util.LifecycleBase setStateInternal
FINE: Setting state for [StandardEngine[Catalina]] to [INITIALIZING]
tomcat: FINE: org.apache.catalina.util.LifecycleBase setStateInternal
FINE: Setting state for [StandardEngine[Catalina]] to [INITIALIZED]
tomcat: FINE: org.apache.catalina.util.LifecycleBase setStateInternal
FINE: Setting state for [Connector[HTTP/1.1-8080]] to [INITIALIZING]
tomcat: FINE: org.apache.catalina.util.LifecycleBase setStateInternal
FINE: Setting state for [org.apache.catalina.connector.MapperListener@737996a0] to [INITIALIZING]
tomcat: FINE: org.apache.catalina.util.LifecycleBase setStateInternal
FINE: Setting state for [org.apache.catalina.connector.MapperListener@737996a0] to [INITIALIZED]
tomcat: FINE: org.apache.catalina.util.LifecycleBase setStateInternal
FINE: Setting state for [Connector[HTTP/1.1-8080]] to [INITIALIZED]
tomcat: FINE: org.apache.catalina.util.LifecycleBase setStateInternal
FINE: Setting state for [StandardService[Catalina]] to [INITIALIZED]
tomcat: FINE: org.apache.catalina.util.LifecycleBase setStateInternal
FINE: Setting state for [StandardServer[8005]] to [INITIALIZED]
tomcat: FINE: org.apache.catalina.util.LifecycleBase setStateInternal
FINE: Setting state for [StandardServer[8005]] to [STARTING_PREP]
tomcat: FINE: org.apache.catalina.core.NamingContextListener lifecycleEvent
FINE: Bound StandardServer[8005]
tomcat: FINE: org.apache.catalina.core.NamingContextListener createNamingContext
FINE: Creating JNDI naming context
tomcat: FINE: org.apache.catalina.core.NamingContextListener addResource

Same question applies, why don't all lines start with tomcat:?

UPDATE While debugging I discovered that BOTH LINES of each log entry come from java.util.logging.Logger.logp()

Answer 1

My logging.properties in Eclipse

1. I do not know how your workspace is configured. Maybe that file is not used at all.

   Java Logging is configured by system properties.

   You need one property (-Djava.util.logging.manager) to configure org.apache.juli.ClassLoaderLogManager as log manager implementation for Java Logging.

   You need other property (-Djava.util.logging.config.file) to configure path to the configuration file.

   Usually both properties are set by the launch script (catalina.sh, catalina.bat), but Eclipse launches java directly, without a help from that script, so those system properties have to be set explicitly in a launch configuration.

   http://tomcat.markmail.org/thread/vpr7mjxmgdvkl3dv

2. Tomcat JULI supports per-classloader configuration of logging.

   This feature allows one to configure logging individually for each web application by packing a WEB-INF/classes/logging.properties file with it.

   If you have unexpectedly placed a logging.properties file into classpath, it will have the same effect: it will supersede the default configuration for classes loaded by that classloader.

   E.g. it is known that some version of Jollyday library (4 years ago) included an unexpected logging.properties file that enabled FINE logging.

   .level = ALL

   https://bz.apache.org/bugzilla/show_bug.cgi?id=52011

Answer 2

The answer has been staring us in the face, from the top of the posting:

java.util.logging.SimpleFormatter.format=JUL %4$s: %2$s%n%4$s: %5$s%n
                                                       ^^^^^^^

The extra %n%4$s: in the format string is what causes the additional line to show up. Duh.