TDS Monitoring and Debugging

Tomcat Access Logs

The Tomcat access log

The access log records all requests processed by the server.
As of Tomcat 7, enabled in Tomcat by default 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.
In order to use the TdsMonitor tool, you will need to change the default configuration of the AccessLogValve.

Configuring Tomcat access logging for the `TdsMonitor`

Modify the prefix, suffix, and pattern attributes of the AccessLogValve element.

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">

  <!-- SingleSignOn valve, share authentication between web applications
       Documentation at: /docs/config/valve.html -->
  <!--
  <Valve className="org.apache.catalina.authenticator.SingleSignOn" />
  -->

  <!-- Access log processes all example.
       Documentation at: /docs/config/valve.html
       Note: The pattern used is equivalent to using pattern="common" -->
  <Valve className="org.apache.catalina.valves.AccessLogValve" directory="logs"
         prefix="localhost_access_log." suffix=".txt"
         pattern="%h %l %u %t "%r" %s %b" />

</Host>

Change the prefix and suffix attributes to customize the access log name. (The TdsMonitor tool looks for log files to begin with access.)

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 &quot;%r&quot; %s %b &quot;%{Referer}i&quot; &quot;%{User-Agent}i&quot; %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" />

Verify the changes to the access log have taken affect.

Restart Tomcat and verify an access log has been generated in the ${tomcat_home}/logs/ directory:

$ ls -l /home/tds/workshop/apache-tomcat-7.0.32/logs
-rw-r--r-- 1 tds ustaff 2444 Oct 21 12:26 access.2012-10-21.log
-rw-r--r-- 1 tds ustaff 7470 Oct 21 12:26 catalina.2012-10-21.log
-rw-r--r-- 1 tds ustaff 7583 Oct 21 12:26 catalina.out
-rw-r--r-- 1 tds ustaff    0 Oct 21 12:26 host-manager.2012-10-21.log
-rw-r--r-- 1 tds ustaff 2160 Oct 21 12:26 localhost.2012-10-21.log
-rw-r--r-- 1 tds ustaff    0 Oct 21 12:26 manager.2012-10-21.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 &quot;%r&quot; %s %b &quot;%{Referer}i&quot; &quot;%{User-Agent}i&quot; %D"

Access log format

For more information on access log format configuration, see the Tomcat Valve Component Documentation.

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:

127.0.0.1 - admin [21/Oct/2012:12:31:59 -0600] "GET /manager/html HTTP/1.1" 200 17578 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:10.0.7) Gecko/20120829 Firefox/10.0.7" 8

Another way of looking at it:

Remote host	`127.0.0.1`
Remote logical username from identd	`-`
Authenticated user	`admin`
Time and date of request	`[21/Oct/2012:12:31:59 -0600]`
HTTP request method	`GET`
Request URI	`/manager/html`
Protocol used	`HTTP/1.1`
HTTP server response	`200`
Bytes transferred	`17578`
Referer	`-`
User Agent	`Mozilla/5.0 (X11; Linux x86_64; rv:10.0.7) Gecko/20120829 Firefox/10.0.7`
Response time (in millis)	`8`

Log Files Generated by the TDS

Introducing the TDS logging directory: `${tomcat_home}/content/thredds/logs`

Keep in Mind

There are two locations of log files you will reference:

${tomcat_home}/logs/ is where you go to look at Tomcat-generated log files; and
the TDS logging directory which is where you go to look at TDS-generated log files.

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

Log file	Data the file contains
`threddsServlet.log`	Each request that the TDS responds to gets logged here, including errors and warnings that are associated with a request.
`serverStartup.log`	As TDS starts up, it logs messages heren (usually only interesting if TDS is failing to start).
`models.log`	Contains log messages specific to gridded model data, especially GRIB data.
`cache.log`	Cache scour messages are kept here (only interesting if you are having problems with cache directories getting too large).
`featureCollectionScan.log`	Contains log messages about feature collection scanning (only used if you use feature collections).
`catalogInit.log`	Errors and warnings in your catalog configuration files are shown here.

About the `threddsServlet.log`

Enabled by default.
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

Look at the logging configurations for threddsServlet.log.

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

$ cd /home/tds/workshop/apache-tomcat-7.0.32/webapps/thredds/WEB-INF
$ less log4j.xml

The TDS uses the OpenSource Apache Log4J library (hence, the name of the file: 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>

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:

2012-10-21T12:26:23.727 -0600 [      5887][       8] INFO  - threddsServlet - Remote host: 127.0.0.1 - Request: "GET /thredds/catalog/testAll/catalog.html?dataset=testDatasetScan/2004050412_eta_211.nc HTTP/1.1"

Another way of looking at it:

Time and date	`2012-10-21T12:26:23.727 -0600`
The number of milliseconds since the server was started	`[ 5887]`
Request ID	`[ 8]`
Logging level	`INFO`
Location in the TDS code where the message was generated	`threddsServlet`
Content of the log message	`Remote host: 127.0.0.1 - Request: "GET /thredds/catalog/testAll/catalog.html?dataset=testDatasetScan/2004050412_eta_211.nc 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 404 (File 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:

2012-10-22T17:31:52.705 -0600 [      5790][       4] INFO  - threddsServlet - Remote host: 127.0.0.1 - Request: "GET /thredds/dodsC/badAggy.html HTTP/1.1"

2012-10-22T17:31:52.752 -0600 [      5837][       4] ERROR - thredds.server.opendap.OpendapServlet - path= /badAggy.html
java.lang.IllegalStateException: There are no datasets in the aggregation DatasetCollectionManager{ collectionName='/data/model/**/.nc' recheck=null 
 dir=/data/model/ filter=WildcardMatchOnPath{wildcard=*.nc$ regexp=.*\.nc$}
	at ucar.nc2.ncml.Aggregation.makeDatasets(Aggregation.java:475)
	at ucar.nc2.ncml.Aggregation.finish(Aggregation.java:401)
...
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
	at java.lang.Thread.run(Thread.java:722)

2012-10-22T17:31:52.755 -0600 [      5840][       4] INFO  - threddsServlet - Request Completed - 500 - -1 - 50

Keep in Mind

Log messages from multiple requests can be interspersed in the log file.

In the above example, note:

the request ID (4) 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) .

Exercise One: Find an example of error transition bracketing in your own `threddsServlet.log`.

Let's generate an error and look at the result in the threddsServlet.log. We are going to tell the TDS to aggregate multiple datasets into a single dataset, BUT we are erroneously going to configure it to scan a directory that doesn't exist.

Open up ${tomcat_home}/content/thredds/catalog.xml and add the following:

<dataset name="badAggy" ID="badAggy" urlPath="badAggy">
   <metadata inherited="true">
        <serviceName>odap</serviceName>
   </metadata>
   <netcdf xmlns="http://www.unidata.ucar.edu/namespaces/netcdf/ncml-2.2">
       <aggregation dimName="time" type="joinExisting">
           <scan location="/data/model/" suffix=".nc" />
       </aggregation>
   </netcdf>
</dataset>

Stop and restart Tomcat and view the result of your addition the TDS main catalog: http://localhost:8080/thredds/catalog.html. You should see a new dataset listed with the name of badAggy:

Click on the badAggy dataset and try to access it via OPeNDAP:

The result should be a 500 (Internal Server Error) (which is the error we sought to create):

Use the grep command to find out which threddsServlet.log file contains the error message:

$ cd /home/tds/workshop/apache-tomcat-7.0.32/content/thredds/logs
$ grep ERROR threddsServlet.log*

Open the threddsServlet.log file which contains the error message and find all the message transaction entries that correspond to that error.
Extra credit: do you see any requests in the threddsServlet.log resulting in a 404 (File Not Found)?
Delete the erroneous entry you made to ${tomcat_home}/content/thredds/catalog.xml and stop/restart Tomcat.

Monitoring and Debugging Tools

Log analyzers

There are a variety of OpenSource and commercial log analysis packages you may wish to employ.

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.

Exercise Two: Use Live HTTP Headers.

Clear any authenticated browser sessions you may have running.
Open Live HTTP Headers
Go to the Tomcat manager application in your browser: http://localhost:8080/manager/html/ and login.
Look at the resulting output in the Live HTTP Headers window.

Tools that come with the JDK: `JVisualVM` and `JConsole`

`JVM` monitoring tools

JVisualVM - Java Virtual Machine Monitoring, Troubleshooting and Profiling Tool.
JConsole - Java Monitoring and Management Console.

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:

generate and analyze heap data
track down memory leaks
monitor the garbage collector and perform memory and CPU profiling
browse and operate on MBeans

Exercise Three: Use either `JVisualVM` or `JConsole`

Launch either JVisualVM or JConsole to track the JVM running Tomcat.

Move into the $JAVA_HOME/bin directory and invoke either jvisualvm or jconsole:

$ cd /home/tds/workshop/jdk1.7.0_09/bin
$ ./jvisualvm

$ cd /home/tds/workshop/jdk1.7.0_09/bin
$ ./jconsole

Find and examine at the JVM arguments and System properties for the Tomcat JVM.
Start and stop the TDS using the Tomcat manager application and examine the result in the CPU usage, Class loading, live Threads count, Heap memory and PermGen memory.
What is the PermGen memory limit? Try to drive the PermGen to it's limit via the manager application. Are you successful?

Unidata

TDS Monitoring and Debugging

Tomcat Access Logs

The Tomcat access log

Configuring Tomcat access logging for the TdsMonitor

Access log format

Access log format

Log Files Generated by the TDS

Introducing the TDS logging directory: ${tomcat_home}/content/thredds/logs

Keep in Mind

About the threddsServlet.log

threddsServlet.log log format

Log4J library

Transaction bracketing in threddsServlet.log

Start of transaction

End of transaction

Looking at threddsServlet.log data

Keep in Mind

Exercise One: Find an example of error transition bracketing in your own threddsServlet.log.

Monitoring and Debugging Tools

Log analyzers

Firefox Add-on: Live HTTP Headers

Exercise Two: Use Live HTTP Headers.

Tools that come with the JDK: JVisualVM and JConsole

JVM monitoring tools

Exercise Three: Use either JVisualVM or JConsole

Configuring Tomcat access logging for the `TdsMonitor`

Introducing the TDS logging directory: `${tomcat_home}/content/thredds/logs`

About the `threddsServlet.log`

`threddsServlet.log` log format

`Log4J` library

Transaction bracketing in `threddsServlet.log`

Looking at `threddsServlet.log` data

Exercise One: Find an example of error transition bracketing in your own `threddsServlet.log`.

Tools that come with the JDK: `JVisualVM` and `JConsole`

`JVM` monitoring tools

Exercise Three: Use either `JVisualVM` or `JConsole`