java - How to configure GlassFish logging to show milliseconds in timestamps?

Question

I have to admit, configuring logging has me a bit baffled :(..., so I hope that someone here can help.

Basically, I need to configure the logging to server.log so that the timestamps include milliseconds.

The thing is, it looks like the default logging.properties is configured for that, but the actual log messages don't look anything like the format string that is the logging.properties, so I can't figure out:

1) What (file) exactly is controlling the log format messages in server.log 2) What do I need to change in, presumably the GlassFish logging.properties, to use the format that is in logging.properties, so that I see milliseconds in the log timestamps?

Here's my current logging.properties:

#GlassFish logging.properties list
#Thu Jan 19 11:44:17 EST 2012

# 02-05-2012 - try to isolate auditing of permit/deny
com.sun.enterprise.security.auth.level=INFO

javax.enterprise.system.tools.admin.level=INFO
#handlers=java.util.logging.ConsoleHandler,com.sun.enterprise.server.logging.GFFileHandler

handlers=com.sun.enterprise.server.logging.GFFileHandler

#java.util.logging.ConsoleHandler.formatter=com.sun.enterprise.server.logging.UniformLogFormatter
com.sun.enterprise.server.logging.GFFileHandler.logFormatDateFormat=yyyy-MM-dd'T'HH:mm:ss.SSSZ
javax.enterprise.system.ssl.security.level=INFO
org.apache.jasper.level=INFO
com.sun.enterprise.server.logging.GFFileHandler.flushFrequency=1
org.eclipse.persistence.session.level=INFO
javax.enterprise.system.tools.backup.level=INFO
javax.enterprise.resource.corba.level=INFO
javax.enterprise.resource.webcontainer.jsf.resource.level=INFO
javax.enterprise.system.core.classloading.level=INFO
javax.enterprise.resource.jta.level=INFO
java.util.logging.ConsoleHandler.level=FINER
com.sun.enterprise.server.logging.GFFileHandler.file=${com.sun.aas.instanceRoot}/logs/server.log

javax.enterprise.system.webservices.saaj.level=INFO
java.util.logging.FileHandler.formatter=java.util.logging.XMLFormatter
javax.enterprise.system.tools.deployment.level=INFO
javax.enterprise.system.container.ejb.level=INFO
javax.enterprise.system.core.transaction.level=INFO
org.apache.catalina.level=INFO
javax.enterprise.resource.webcontainer.jsf.lifecycle.level=INFO
com.sun.enterprise.server.logging.GFFileHandler.rotationTimelimitInMinutes=0
javax.enterprise.resource.webcontainer.jsf.config.level=INFO
javax.enterprise.system.container.ejb.mdb.level=INFO
javax.enterprise.resource.webcontainer.jsf.timing.level=INFO

# 02-05-2012 - try to isolate auditing of permit/deny
javax.enterprise.system.core.level=FINE

com.sun.enterprise.server.logging.GFFileHandler.rotationOnDateChange=false

org.apache.coyote.level=INFO
ShoalLogger.level=INFO
javax.level=INFO
javax.enterprise.resource.webcontainer.jsf.taglib.level=INFO
java.util.logging.FileHandler.limit=50000
javax.enterprise.system.webservices.rpc.level=INFO
javax.enterprise.resource.javamail.level=INFO
com.sun.enterprise.server.logging.GFFileHandler.logtoConsole=false
javax.enterprise.system.container.web.level=INFO
javax.enterprise.resource.webcontainer.jsf.facelets.level=INFO
javax.enterprise.resource.resourceadapter.level=INFO
javax.enterprise.system.util.level=INFO
com.sun.enterprise.server.logging.GFFileHandler.level=ALL
javax.org.glassfish.persistence.level=INFO
javax.enterprise.resource.webcontainer.jsf.context.level=INFO
javax.enterprise.resource.webcontainer.jsf.application.level=INFO
javax.enterprise.resource.jms.level=INFO
javax.enterprise.system.core.config.level=INFO
com.sun.enterprise.server.logging.GFFileHandler.rotationLimitInBytes=2000000
org.jvnet.hk2.osgiadapter.level=INFO
javax.enterprise.system.level=INFO

# 02-05-2012 - try to isolate auditing of permit/deny
javax.enterprise.system.core.security.level=INFO

javax.enterprise.system.container.cmp.level=INFO
java.util.logging.FileHandler.pattern=%h/java%u.log
com.sun.enterprise.server.logging.SyslogHandler.useSystemLogging=false
javax.enterprise.resource.sqltrace.level=INFO
javax.enterprise.resource.webcontainer.jsf.renderkit.level=INFO
javax.enterprise.system.webservices.registry.level=INFO
javax.enterprise.system.core.selfmanagement.level=INFO

# 02-05-2012 - try to isolate auditing of permit/deny
com.sun.enterprise.security.Audit.level=INFO
com.sun.enterprise.security.level=INFO

com.sun.enterprise.server.logging.GFFileHandler.formatter=com.sun.enterprise.server.logging.UniformLogFormatter.level=FINE
com.sun.enterprise.server.logging.GFFileHandler.maxHistoryFiles=0
log4j.logger.org.hibernate.validator.util.Version=warn
java.util.logging.FileHandler.count=1

# 02-05-2012 - try to isolate auditing of permit/deny
com.sun.enterprise.security.auth.realm.level=INFO

javax.enterprise.resource.webcontainer.jsf.managedbean.level=INFO
org.glassfish.admingui.level=INFO
javax.enterprise.system.core.naming.level=INFO
javax.enterprise.resource.jdo.level=INFO
com.sun.enterprise.server.logging.GFFileHandler.retainErrorsStasticsForHours=0
security.level=FINE
LDAPRealm.level=FINE

You'll notice that the .logFormatDateFormat with a format, but what I get in the actual server.log looks totally different that that format, e.g.:

Feb 5, 2012 2:30:44 PM com.sun.enterprise.v3.server.GFDomainXml
FINE: Total time to parse domain.xml: 516 milliseconds

So it seems like some other configuraition file, other than what I have in the GF logging.properties is in control?

Thanks, Jim

Answer 1

The output looks like the default j.u.l.SimpleFormatter. The Q conversion conversion pattern is milliseconds since the beginning of the epoch. Change the format of the SimpleFormatter using the system property:

-Djava.util.logging.SimpleFormatter.format="%1$tQ %2$s%n%4$s: %5$s%6$s%n"

or in the logging.properties:

java.util.logging.SimpleFormatter.format=%1$tQ %2$s%n%4$s: %5$s%6$s%n

The L conversion pattern is millisecond within the second formatted as three digits. The default pattern can be modified using the system property as:

-Djava.util.logging.SimpleFormatter.format="%1$ta %1$tb %1$td, %1$tY %1$tl:%1$tM:%1$tS.%1$tL %1$Tp %2$s%n%4$s: %5$s%n"

or in the logging.properties:

java.util.logging.SimpleFormatter.format=%1$ta %1$tb %1$td, %1$tY %1$tl:%1$tM:%1$tS.%1$tL %1$Tp %2$s%n%4$s: %5$s%n

All of these properties are documented in the format method and in the java.util.Formatter class.