Login/Register
Tomcat7 logging hell - why two different formats coming out?
Asked Answered
Solved linuxeclipseloggingtomcat7java.util.logging
K

4

7

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() enter image description here

Kelm answered 26/9, 2015 at 19:10 Comment(0)
K
1

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.

Kelm answered 11/10, 2015 at 6:31 Comment(0)
B
3

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

Barrington answered 11/10, 2015 at 0:32 Comment(1)
This didn't actually answer my question but thanks for shedding light into tomcat's initialization process, that explains a lot. – Kelm
K
1

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.

Kelm answered 11/10, 2015 at 6:31 Comment(0)
L
0

The info messages you are referring to is not actually part of core. They are being generated by classes in different packages. By dissecting catalina libs and identifying the classes responsible for particular logs, here is the configuration which has prevented logs on tomcat 7.0.63, by appending to default logging.properties:

org.apache.catalina.startup.level=OFF
org.apache.catalina.startup.handlers=1catalina.org.apache.juli.FileHandler.level

org.apache.catalina.core.level=OFF
org.apache.catalina.core.handlers=1catalina.org.apache.juli.FileHandler.level

org.apache.coyote.level=OFF
org.apache.coyote.handlers=1catalina.org.apache.juli.FileHandler.level
Luht answered 10/10, 2015 at 10:8 Comment(1)
It always envious when someone finds something which someone could not figure out! – Luht
B
-1

I think you're missing jul-to-slf4j. See here for more detail slf4j legacy bridge documentation

Benedetto answered 26/9, 2015 at 20:29 Comment(1)
That doesn't solve this particular problem. After installing jul-to-slf4j and configuring the bridge, I was able to redirect all messages to logback, but I'm still getting the two distinct types of messages. – Kelm

© 2022 - 2024 — McMap. All rights reserved.