TDS Tutorial: TDS Monitoring and Debugging

The Tomcat access log

• The access log records all requests processed by the server.
• Not enabled in Tomcat by default - must be enabled in $TOMCAT_HOME/conf/server.xml.
• Information it contains is different from other logs in $TOMCAT_HOME/logs.
• Used for monitoring who is using your server and as a way of obtaining "feedback" about the activity and performance of the server.

Configuring Tomcat to enable access logging

1. Modify server.xml to enable the AccessLogValve.

Using your favorite editor open $TOMCAT_HOME/conf/server.xml:

$ vi server.xml

Locate the AccessLogValve contained in the Host element (should be near the bottom of the file):

<!-- Define the default virtual host
        Note: XML Schema validation will not work with Xerces 2.2.
-->
<Host name="localhost"  appBase="webapps"
      unpackWARs="true" autoDeploy="true"
      xmlValidation="false" xmlNamespaceAware="false">

  . . .
  
  <!-- Access log processes all example.
          Documentation at: /docs/config/valve.html -->
  <!--
  <Valve className="org.apache.catalina.valves.AccessLogValve" directory="logs"  
            prefix="localhost_access_log." suffix=".txt" pattern="common" resolveHosts="false"/>
  -->

</Host>

Uncomment the AccessLogValve and change the prefix and suffix attributes to customize the access log name:

prefix="access." 
suffix=".log"

To provide more useful information about who is accessing the TDS, change the pattern element to customize the format of each log entry:

pattern="%h %l %u %t "%r" %s %b "%{Referer}i" "%{User-Agent}i" %D"

When you are finished with your edits, the AccessLogValve should look something like the following:

<Valve className="org.apache.catalina.valves.AccessLogValve"
   directory="logs"  
   prefix="access." 
   suffix=".log"
   pattern="%h %l %u %t &quot;%r&quot; %s %b &quot;%{Referer}i&quot; &quot;%{User-Agent}i&quot; %D"
   resolveHosts="false" />

2. Verify the access log has been enabled.

Restart Tomcat and verify an access log with a name format of access.yyyy-mm-dd.log has been generated in the $TOMCAT_HOME/logs/ directory:

$ ls -l /home/thredds/apache-tomcat-6.0.20/logs/access*
-rw-r--r-- 1 thredds workshop 0 2009-08-04 13:22 access.2009-08-04.log

Access log format

The access log entry format we are using is almost identical to the standard combined logging format with an addition: the %D which is used for documenting the Time taken to process the request, in millis will appear at the end of each log entry:

pattern="%h %l %u %t "%r" %s %b "%{Referer}i" "%{User-Agent}i" %D"

The above pattern makes use of the following codes:

• %h - Remote host name (or IP address if resolveHosts is false)
• %l - Remote logical username from identd (always returns '-')
• %u - Remote user that was authenticated (if any), else '-'
• %t - Date and time, in Common Log Format
• %r - First line of the request (method and request URI)
• %s - HTTP status code of the response
• %b - Bytes sent, excluding HTTP headers, or '-' if zero
• %D - Time taken to process the request, in millis

The above pattern translates into:

128.117.140.183 - oxelson [09/Jul/2009:20:23:46 -0700] "GET /manager/html HTTP/1.1" 200 13022 "http://localhost:8080/" 
"Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.0.3) Gecko/2008092417 Firefox/3.0.3" 325

Another way of looking at it:

Looking at access log data

Storing the information in the access log is only the start of log management. The next step is to analyze this information to produce useful statistics.

1. Looking at raw access log data.

Locate the access.2009.07.27.log file in your home directory which contains an access log file taken from one of our production servers.

$ cd
$ ls -l access* 
-rw-r--r--  1 thredds workshop 350361 2009-08-04 13:14 access.2009-07-27.log

Have a look at the log file and try to examine the data stored there. (Kind of hard to sort through it all, isn't it)?

$ less access.2009-07-27.log

2. Analyzing data subsets with awk and dig.

Sometimes we don't need to see the "whole picture" and just need some quick statistics. E.g., we need to find the host that has made the most requests to the server.

Run the following command:

$ cat access.2009-07-27.log | awk '{print $1}' | sort | uniq -c | sort -n
   6 198.181.231.27
 168 128.117.140.75
 927 192.12.209.93
1115 192.12.209.57

The output of the access log file is piped into awk, which prints the first "field variable" $1. The result is sorted, identical lines are counted, and finally sorted again in descending order.

192.12.209.57 is the host that has made the most requests to the server during this particular access log's period.

But who is 192.12.209.57? (IPs are not too meaningful by themselves.)

Run dig to find out the host information for 192.12.209.57:

$  dig +short -x 192.12.209.57
atm.cise-nsf.gov.

atm.cise-nsf.gov is the host name for 192.12.209.57 (a bit more meaningful).

Looking at the other IP addresses from the awk output. Without running dig, what do you think the domain of 192.12.209.93 is going to be?

See if your assumption is correct:

$  dig +short -x 192.12.209.93
cise093.cise-nsf.gov.

Run dig on the other addresses to get the host names for the other two remaining IPs:

$  dig +short -x 128.117.140.75
newhart.unidata.ucar.edu.
$  dig +short -x 198.181.231.27
hirudo.nsf.gov.

Introducing the TDS logging directory: $TOMCAT_HOME/content/thredds/logs

The log files generated by the TDS are located in the $TOMCAT_HOME/content/thredds/logs directory:

About the threddsServlet.log

• Already enabled.
• Log messages for all requests handled by the TDS.
• By default is configured to rotate every hour. Old log files are re-named with the threddsServlet.log.<yyyy-mm-dd-HH> pattern.
• Used for debugging and troubleshooting issues with the TDS.
• May be asked to send information from threddsServlet.log to the TDS development team when seeking support.

threddsServlet.log log format

1. Look at the logging configurations for threddsServlet.log.

Navigate to the unpacked thredds directory in $TOMCAT_HOME/webapps, and view the WEB-INF/log4j.xml:

$ cd /home/thredds/apache-tomcat-6.0.20/webapps/thredds
$ less WEB-INF/log4j.xml

The TDS uses the OpenSource Apache Log4J library (hence, the name of the file: WEB-INF/log4j.xml).

Find the first uncommented Appender element with a name of threddsServlet and a class of org.apache.log4j.DailyRollingFileAppender, and note the ConversionPattern:

  <appender name="threddsServlet" class="org.apache.log4j.DailyRollingFileAppender">
    <param name="File" value="${tds.log.dir}/threddsServlet.log"/>
    <param name="DatePattern" value=".yyyy-MM-dd-HH"/>
    <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"/>
      <!--param name="ConversionPattern" value="%d{ISO8601} [%10r - %10X{ID}] %-5p - %c - %m%n"/-->
    </layout>
  </appender>     

2. Examine the log format being applied to the threddsServlet.log file.

The ConversionPattern parameter specifies the Log4J pattern used to format the entries of the threddsServlet.log file:

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

Log4J library

For more information on the Log4J library, consult the online documentation.

The above pattern makes use of the following Log4J codes:

• %d{yyyy-MM-dd'T'HH:mm:ss.SSS Z} - Date and time
• %10r - Time, in millis, since Tomcat startup
• %8X{ID} - Transaction ID
• %-5p - Logging level (options are DEBUG, INFO, WARN, ERROR, and FATAL)
• %c - Location in the TDS code where the message was generated
• %m - Content of the log message
• %n - Newline character

The above pattern translates into:

2009-08-03T14:02:28.184 -0600 [1044713597][  214877] INFO  - thredds.server.catalogservice.LocalCatalogServiceController - handleRequestInternal(): Remote host: 192.87.16.142 - Request: "GET /thredds/catalog/nexrad/level3/NVL/VAX/20090619/catalog.xml HTTP/1.1"

Another way of looking at it:

Time and date	2009-08-03T14:02:28.184 -0600
The number of milliseconds since the server was started	[1044713597]
Request ID	[ 214877]
Logging level	INFO
Location in the TDS code where the message was generated	thredds.server.catalogservice.LocalCatalogServiceController - handleRequestInternal()
Content of the log message	Remote host: 192.87.16.142 - Request: "GET /thredds/catalog/nexrad/level3/NVL/VAX/20090619/catalog.xml HTTP/1.1

Transaction bracketing in threddsServlet.log

• Each HTTP request (or transaction) handled by the TDS results in at least two log messages:
• a message indicating the start of the transaction; and
• a message indicating the end of the transaction.
• Between the start and end messages, there may be other entries for this same request (e.g., DEBUG, WARN, ERROR, etc.).
• All log messages for the same request will have the same request ID.
• Log messages from multiple requests can be interspersed in the log file.
• When tracking down an error, it is useful to find a specific example of a request that causes that error and extract all the log messages for that request.

Start of transaction

The main message in a start of transaction log message includes:

• IP address of the requester; and
• request being made.

For example:

... Remote host: 128.117.140.75 - Request: "GET /thredds/catalog.html HTTP/1.1"

End of transaction

The main message in a end of transaction log message includes:

• server response code for the response;
• size of the response body in bytes; and
• time (in milliseconds) to handle the request.

For example:

... Request Completed - 200 - 3403 - 1

Most end of transaction messages include a status code that matches a standard HTTP status code. However, when the client breaks the connection or a request is forwarded to another TDS internal service, one of three TDS specific status codes are used:

• "1000 (Client Abort)" - the connection to the client was broken;
• "1001 (Forwarded)" - the request was forwarded to another TDS internal service; or
• "1002 (Forward Failed)" - an attempt was made but failed to forward the request to another TDS internal service.

If the request is forwarded successfully, another set of transaction messages should be initiated with the ending message containing a standard HTTP status code. If forwarding the request fails, another set of transaction message may or may not be initiated and the entry in the access log will probably either log a 400 (Not Found) or a 500 (Internal Server Error) HTTP status code.

Looking at threddsServlet.log data

Here is an example of some log messages from a request that resulted in error messages:

2009-06-03T21:49:07.147 -0600 [ 104481318][   27031] INFO  - thredds.server.opendap.OpendapServlet - Remote host: 128.117.140.75 - Request: "GET /thredds/dodsC/nexrad/level2/KFTG/20090602/Level2_KFTG_20090602_0346.ar2v.dds HTTP/1.1"
2009-06-03T21:49:07.415 -0600 [ 104481586][   27031] ERROR - thredds.server.opendap.OpendapServlet - path= /nexrad/level2/KFTG/20090602/Level2_KFTG_20090602_0346.ar2v.dds
java.io.IOException: Cant read /data/ldm/pub/native/radar/level2/KFTG/20090602/Level2_KFTG_20090602_0346.ar2v: not a valid NetCDF file.
        at ucar.nc2.NetcdfFile.open(NetcdfFile.java:716)
        at ucar.nc2.NetcdfFile.open(NetcdfFile.java:381)
 ...
        at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
        at java.lang.Thread.run(Thread.java:619)
2009-06-03T21:49:07.416 -0600 [ 104481587][   27031] INFO  - thredds.server.opendap.OpendapServlet - Request Completed - 500 - -1 - 269

In the above example, note:

• the request ID (27031) matches in all messages;
• the ERROR message contains a stack trace; and
• the status code in the end of transaction message is 500 (Internal Server Error) .

Log analyzers

There are a variety of OpenSource and commercial log analysis packages you may wish to employ. Below are some resources to help locate a package:

• Log Analysis category at Open Directory Project
• List of log analysis tools at Counterguide.com
• Log Analysis Tools category at Yahoo Directory

Firefox Add-on: Live HTTP Headers

• "Free" Firefox add-on
• Live HTTP Headers is accessed through the Firefox Tools menu.
• Host, server, and cookie information is displayed in the first tab.
• Once it's running, it automatically updates if you move to a new page.
• The Generator tool shows redirects, images, and CSS on a page.
• It's easy to check and uncheck options to view.
• Information is easily saved in text files.

Tools that come with the JDK: JConsole and JVisualVM

• Both come packaged with the JDK (found in $JAVA_HOME/bin).
• Both GUI tools to provide information about the JVM in a visual format.
• Used for monitoring, troubleshooting, and profiling what is happening in the JVM.

1. Use JConsole to track the JVM running Tomcat.

Invoke the jconsole program in $JAVA_HOME/bin:

$ cd $JAVA_HOME/bin
$ ./jconsole

If you happen to be running more than one JVM on your machine, look to see what Process ID # for the JVM running Tomcat:

$ ps -ef | grep tomcat
thredds   5168     1  5 14:01 pts/2    00:00:12 /home/thredds/jdk1.6.0_14/bin/java -Djava.util.logging.config.file=/home/thredds/apache-tomcat-6.0.20/conf/logging.properties -Xmx256m -Xms256m -server -Djava.awt.headless=true -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Djava.endorsed.dirs=/home/thredds/apache-tomcat-6.0.20/endorsed -classpath :/home/thredds/apache-tomcat-6.0.20/bin/bootstrap.jar -Dcatalina.base=/home/thredds/apache-tomcat-6.0.20 -Dcatalina.home=/home/thredds/apache-tomcat-6.0.20 -Djava.io.tmpdir=/home/thredds/apache-tomcat-6.0.20/temp org.apache.catalina.startup.Bootstrap start
thredds   5451  4285  0 14:05 pts/2    00:00:00 grep tomcat

Select the local JVM process corresponding to Tomcat and connect:



2. Try to create a PermGen error via the Tomcat manager application.

In your browser window, continually Start, Stop and reload the TDS and other web applications using the manager application.

In the meantime, chart the Memory Pool "PS Perm Gen" in the JConsoleMemory tab. Also monitor the Heap Memory Usage and Class Loading displays in the Overview tab.

3. Try to create a PermGen error via the Tomcat manager application.
4. Identify PermGen as it happens.

The PermGen error manifests itself in the following ways:

1. The manager application stops responding.
2. JConsole will loose its connection with the Tomcat JVM:



3. The following error is reported in catalina.out:

Exception in thread "RMI TCP Connection(idle)" java.lang.OutOfMemoryError: PermGen space

4. In the two JConsole screen captures below, you can see the memory usage of PermGen increased with every reload of the application until it reaches the point where the JVM crashes with the OutOfMemory error. The default maximum PermGen amount of JVM is 64 MB.