TDS Logging

Log4J

TDS uses the Log4J library, currently contained in the NLOG4J library which implements the SLF4J logging facade, which the Netcdf-Java library uses. Users of the TDS can ignore the SLF4J facade, and need only deal with log4j.

The default log4j configuration file is shipped inside the TDS war file. Once the thredds.war file is expanded, you can find it at ${tomcat_home}/webapps/thredds/WEB-INF/log4j.xml. You can modify this if you want and restart the TDS to have it take efffect. However, it will be overwritten when you install an updated thredds.war file.

You can change the location of the log4j configuration file with the log4j-init-file context parameter in the thredds configuration file ${tomcat_home}/webapps/thredds/WEB-INF/web.xml. file. For example:

 <context-param>
   <param-name>log4j-init-file</param-name>
   <param-value>/data/mylog4j.xml</param-value>
 </context-param>

The value should be the absolute path to the log4j configuration file. Remember that web.xml gets overwritten when the thredds.war file is updated.

ThreddsServlet logfile

The ThreddsServlet logs roll over every 10MB, keepin the last 10 files. The log4j entry looks like:

  <appender name="threddsServlet" class="org.apache.log4j.RollingFileAppender">
    <param name="File" value="${logdir}/threddsServlet.log"/>
    <param name="MaxFileSize" value="10MB"/>
    <param name="MaxBackupIndex" value="10"/>
    <layout class="org.apache.log4j.PatternLayout">
      <param name="ConversionPattern" value="%d{yyyy-MM-dd'T'HH:mm:ss.SSS Z} [%10r][%8X{ID}] %-5p - %c - %m%n"/>
    </layout>
  </appender>

As you can see, the PatternLayout looks like:

  "%d{yyyy-MM-dd'T'HH:mm:ss.SSS Z} [%10r][%8X{ID}] %-5p - %c - %m%n"

An example entry looks like:

2006-01-24T17:31:41.452 -0700 [2025609][44] INFO  - thredds.servlet.ServletUtil - Remote host: 128.117.140.172 - Request: "GET /thredds/idd/radars.xml HTTP/1.1"

Field	log4j pattern	example
Date	%d{yyyy-MM-dd'T'HH:mm:ss.SSS Z}	2006-01-24T17:31:41.452 -0700
msec since tomcat startup	[%10r]	[ 2025609]
transaction id	[%8X{ID}]	[ 44]
Logging level	%-5p	INFO
Logger name	%c	thredds.servlet.ServletUtil
message	%m	Remote host: 128.117.140.172 Request: "GET /thredds/idd/radars.xml HTTP/1.1"
newline	%n

MDC fields

The special MDC fields are available to be added to the log, using the syntax X{name}, where name is one of the following:

Name	Meaning
ID	sequential id , for duration of transaction
ident	session.getId()
userid	req.getRemoteUser()
startTime	System.currentTimeMillis()
request	URL request
host	req.getRemoteHost()

Transaction Bracketing

Each HTTP request has at least two entries in the log file, the start and end of the transaction. Other entries may appear between those two (eg debuging, warning, or error message). All entries for the request share the same request ID. For example, here is a request that has 4 entries in the log: 1) start of transaction, 2) warning message, 3) error message (with stacktrace), and 4) end of transaction.

2007-07-19T20:27:16.494 -0600 [ 206833774][   16508] INFO  - thredds.servlet.ServletUtil - Remote host: 66.26.59.117 - Request: "HEAD /thredds/dodsC/nexrad/level2/KRAX/20070720/Level2_KRAX_20070720_0220.ar2v.dds HTTP/1.1"
2007-07-19T20:27:16.777 -0600 [ 206834057][   16508] WARN  - ucar.nc2.iosp.nexrad2.Level2VolumeScan -  No data for = doppler
2007-07-19T20:27:16.796 -0600 [ 206834076][   16508] ERROR - thredds.server.opendap.NcDODSServlet - Error 
java.lang.IllegalStateException: No data for RadialVelocity
	at ucar.nc2.iosp.nexrad2.Nexrad2IOServiceProvider.makeVariable(Nexrad2IOServiceProvider.java:148)
	at ucar.nc2.iosp.nexrad2.Nexrad2IOServiceProvider.open(Nexrad2IOServiceProvider.java:78)
  ...
2007-07-19T20:27:16.800 -0600 [ 206834080][   16508] INFO  - thredds.servlet.ServletUtil - Request Completed - 200 - -1 - 305

Note that the end of transaction shows a status return of 305 - server error. All entries have the same transaction id, and may be interleaved with messages from other request transactions. When tracking down an error, its useful to find a specific example of it in the logs and extract all log messages for that request.

The code that generates the start and end transaction messages:

Start Transaction

log.info( "Remote host: " + req.getRemoteHost() + " - Request: " + request);

End Transaction

logStats.info( resCode + " " + ( ( resSizeInBytes != -1 ) ? String.valueOf( resSizeInBytes ) : "-" ) + " " + duration );
log.info( "Request Completed - " + resCode + " - " + resSizeInBytes + " - " + duration);

This document is maintained by John Caron and was last updated on July 26, 2007