On-going logging problems

[Allen Williams]

Tomcat 6.0, despite having this in my code:

public class AppInitializer implements ServletContextListener
    {
    public void contextInitialized(ServletContextEvent e)
        {
        log2.log(Level.FINEST, "\n************ In contextInitialized **************\n");
        System.out.println("\n************ In contextInitialized **************\n");
        System.out.flush();
        System.err.println("\n************ In contextInitialized **************\n");
        System.err.flush();

<snip>

private static Logger log2= Logger.getLogger("3info-dev.org.apache");

I can't get anything to display in any of the log files. Here is my logging.properties:

# Licensed to the Apache Software Foundation (ASF) under one or more
# contributor license agreements. See the NOTICE file distributed with
# this work for additional information regarding copyright ownership.
# The ASF licenses this file to You under the Apache License, Version 2.0
# (the "License"); you may not use this file except in compliance with
# the License. You may obtain a copy of the License at
#
# http://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing, software
# distributed under the License is distributed on an "AS IS" BASIS,
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
# See the License for the specific language governing permissions and
# limitations under the License.

# Logging levels: SEVERE, WARNING, INFO, CONFIG, FINE, FINER, FINEST or ALL

handlers = 1catalina.org.apache.juli.FileHandler, 2localhost.org.apache.juli.FileHandler, 3info-dev.org.apache.juli.FileHandler, java.util.logging.ConsoleHandler

.handlers = 1catalina.org.apache.juli.FileHandler, java.util.logging.ConsoleHandler
.level=WARNING

############################################################
# Handler specific properties.
# Describes specific configuration info for Handlers.
############################################################

1catalina.org.apache.juli.FileHandler.level = WARNING
1catalina.org.apache.juli.FileHandler.directory = ${catalina.base}/logs
1catalina.org.apache.juli.FileHandler.prefix = catalina.

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

3info-dev.org.apache.juli.FileHandler.level = ALL
3info-dev.org.apache.juli.FileHandler.directory = ${catalina.base}/logs
3info-dev.org.apache.juli.FileHandler.prefix = info-dev.

java.util.logging.ConsoleHandler.level = ALL
java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter

############################################################
# Facility specific properties.
# Provides extra control for each logger.
############################################################

org.apache.catalina.core.ContainerBase.[Catalina].[localhost].level = INFO
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].handlers = 2localhost.org.apache.juli.FileHandler

org.apache.catalina.core.ContainerBase.[Catalina].[info-dev].[/infoisland].level = ALL
org.apache.catalina.core.ContainerBase.[Catalina].[info-dev].[/infoisland].handlers = 3info-dev.org.apache.juli.FileHandler
# org.apache.catalina.core.ContainerBase.[Catalina].[info-dev].[/infoisland].handlers = java.util.logging.ConsoleHandler

utils.AppInitializer.level = ALL

# For example, set the com.xyz.foo logger to only log SEVERE
# messages:
#org.apache.catalina.startup.ContextConfig.level = FINE
#org.apache.catalina.startup.HostConfig.level = FINE
#org.apache.catalina.session.ManagerBase.level = FINE
#org.apache.catalina.core.AprLifecycleListener.level=FINE

and here are the log files that are produced-

catalina.xxx.log:

Aug 8, 2009 7:06:40 PM org.apache.catalina.users.MemoryUserDatabase save
WARNING: User database is not persistable - no write permissions on directory

info-dev.log:

Aug 8, 2009 7:06:41 PM org.apache.catalina.core.StandardContext listenerStart
FINE: Sending application start events
Aug 8, 2009 7:06:41 PM org.apache.catalina.core.StandardContext filterStart
FINE: Starting filters

localhost.log:

<null>, i. e., nothing in log

ANY ideas why my console AND my log file are being sent to a black hole? BTW, I have also set and unset swallowOutput="true" multiple times in my <Context> tag.

[Bear Bibeault]

Windows?

[Allen Williams]

Thanks for taking a stab at this.

Not Windows; Debian Linux 2.6.26, i686

Vanilla Tomcat 6 distribution from Debian apt package.

[Paul Clapham]

This is a question about Tomcat, right? Let's move it to a forum about Tomcat.

[Allen Williams]

I guess it is a tomcat issue, instead of my servlet. Sorry about that; originally, I thought it was an error in my servlet.

In my init.d startup script, I discovered this:

$DAEMON -user "$TOMCAT6_USER" -cp "$JSVC_CLASSPATH" \
-outfile SYSLOG -errfile SYSLOG \
-pidfile "$CATALINA_PID" $JAVA_OPTS "$BOOTSTRAP_CLASS"

(Note the SYSLOG entries) which I changed to this:

$DAEMON -user "$TOMCAT6_USER" -cp "$JSVC_CLASSPATH" \
-outfile /var/log/tomcat6/stdout.log -errfile /var/log/tomcat6/stderr.log \
-pidfile "$CATALINA_PID" $JAVA_OPTS "$BOOTSTRAP_CLASS"

so now I have an stderr and stdout in my log directory, but it still doesn't have any of my System.err.println's in it

[Allen Williams]

Well, I'm not too sure what I did, but now I'm getting the System.err.println messages in the aforementioned stderr.log. After I pointed (in the init.d script) command line arguments (outfile=... and errfile=...) I started getting messages in this file, but none of mine. I looked, and somewhere along the line, I made my <Context> tag this:

<Context path="" docBase="" swallowOutput="true" debug="5"
reloadable="true"
antiResourceLocking="false" privileged="false">

As I'm sure you gurus know, the "debug=" attribute is not a documented attribute for the Context tag (I saw it somewhere, and put it in). Tomcat never did complain, but I removed it, making the Context tag this:

<Context path="" docBase="" swallowOutput="true" reloadable="true"
antiResourceLocking="false" privileged="false">

And now everything works. Not sure what happened. I did not start out with that in the context tag. I'm wondering if maybe I had an OS glitch?

Thanks for all the help!!

anw

[Tim Holloway]

I don't think you understand Java logging.

It's extremely bad practice to "log" by writing to System.out or System.err in a web application. As you have discovered, the actual destination for such "logging" isn't easily determined. In fact, a server could just discard such messages completely and still be considered J(2)EE compliant.

The only really "safe" use for the System io channels is in a stand-alone Java app. In all other venues, you're at the mercy of the framework implementor.

On the other hand, Java supports multiple (probably too many) true logging systems. Things like java.util.log(?package name?) and log4j. It even supports meta-logging to insulate developers from which logger is used and to resolve situations where systems are built from components using multiple types of loggers.

Loggers offer the following advantages over brute-force printing:

1. Timestamping. Generally comes for free

2. Custom filtering. You can suppress detailed messages for normal usage but enable them if you have problems - without editing or recompiling the code.

3. Routability. You can send messages to one or more destinations based on the type and severity of log message - including specialized destinations like paging devices. It's not uncommon to generate summary logs and to log to rotating/archiving logfiles.

4. Custom formatting. You can customize the format of log messages in a number of ways, including how/if you want the timestamp and originating component ID to display.

5. Predictability. YOU determine where the output will go (per item #3, above).

The Tomcat logfile (commonly catalina.out) isn't a Java Logging file for all intents and purposes. It's really the Tomcat console output. And its actual name and location vary considerably depending on what platform you're running Tomcat on.

[Allen Williams]

Yeah, I know, I know. I will not argue with one word you wrote, and in fact thank you for taking the time to do so. I started this app is several years ago, set it aside because I got involved in a circuit design/embedded software project, and just picked it back up. The problem is that I've the custom log calls all through it. When I get it really finished (with kludgy logging), I'm thinking I may be able to go back and redo the logging evolutionarily by first changing my logging class implementation to use standard logging, then gradually replacing all the call throughout the app as I maintain it. I know- right now it's an example of really bad form:-(

Thanks again for the help!

[Tim Holloway]

Allen Williams wrote:Yeah, I know, I know. I will not argue with one word you wrote, and in fact thank you for taking the time to do so. I started this app is several years ago, set it aside because I got involved in a circuit design/embedded software project, and just picked it back up. The problem is that I've the custom log calls all through it. When I get it really finished (with kludgy logging), I'm thinking I may be able to go back and redo the logging evolutionarily by first changing my logging class implementation to use standard logging, then gradually replacing all the call throughout the app as I maintain it. I know- right now it's an example of really bad form:-(

Thanks again for the help!

Been there/done that. Fortunately you can do a bulk search-and-replace on "System.out.println(" to "log.info(" using any popular text editor. And I added a macro key to generate

	/* Logger */
	final Logger log = Logger.getLogger(getClass().getName());

I've gotten real good at it. I inherited an app chock full of printlns!

[Allen Williams]

Thanks again! Now that I'm back on this app, you'll see plenty of me!