TDS Monitoring and Debugging: Logs!

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 workshop 0 Jul 24 12:25 access.2013-07-24.log
-rw-r--r-- 1 tds workshop  4270 Jul 24 12:26 catalina.2013-07-24.log
-rw-r--r-- 1 tds workshop 19095 Jul 24 12:26 catalina.out
-rw-r--r-- 1 tds workshop     0 Jul 24 12:25 host-manager.2013-07-24.log
-rw-r--r-- 1 tds workshop  3845 Jul 24 12:26 localhost.2013-07-24.log
-rw-r--r-- 1 tds workshop     0 Jul 15 09:39 localhost_access_log.2013-07-15.txt
-rw-r--r-- 1 tds workshop     0 Jul 24 12:25 manager.2013-07-24.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
`catalogInit.log`	contains log messages related to configure catalog parsing on startup
`threddsServlet.log`	contains log messages used for debugging
`serverStartup.log`	contains log messages from the initialization of the TDS
`fmrc.log`	contains log messages specific FMRC collections
`cache.log`	contains log messages related to TDS object and file caching
`featureCollectionScan.log`	contains log messages related to feature collections

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:

2013-07-22T09:21:02.229 -0600 [1114883517][ 7948911] INFO  - threddsServlet - Remote host: 173.165.244.157 - Request: "GET /thredds/wms/grib/NCEP/GFS/Global_0p5deg/GFS-Global_0p5deg-20130722/best2013-07-22T12:00:00Z?
LAYERS=Temperature_isobaric&FORMAT=image%2Fpng&TRANSPARENT=TRUE&VERSION=1.3.0&STYLES=boxfill2Frainbow&COLOR
SCALERANGE=270%2C315&ELEVATION=100000&EXCEPTIONS=INIMAGE&SERVICE=WMS&REQUEST=GetMap&TIME=2013-07-22T12%3A00
%3A00.000Z&CRS=EPSG%3A3857&BBOX=-10644926.305625,5635549.220625,-10331840.237812,5948635.2884375&WIDTH=256&
HEIGHT=256 HTTP/1.1"

2013-07-22T09:21:02.233 -0600 [1114883521][ 7948912] INFO  - threddsServlet - Remote host: 173.165.244.157 - Request: "GET /thredds/wms/grib/NCEP/GFS/Global_0p5deg/GFS-Global_0p5deg-20130722/best2013-07-22T12:00:00Z?LAYERS=Temperature_isobaric&FORMAT=image%2Fpng&TRANSPARENT=TRUE&VERSION=1.3.0&STYLES=boxfill2Frainbow&COLOR
SCALERANGE=270%2C315&ELEVATION=100000&EXCEPTIONS=INIMAGE&SERVICE=WMS&REQUEST=GetMap&TIME=2013-07-22T12%3A00
%3A00.000Z&CRS=EPSG%3A3857&BBOX=-10644926.305625,5322463.1528125,-10331840.237812,5635549.220625&WIDTH=256&
HEIGHT=256 HTTP/1.1"

2013-07-22T09:21:02.247 -0600 [1114883535][ 7948897] INFO  - threddsServlet - Request Completed - 200 - -1 - 186

2013-07-22T09:21:02.364 -0600 [1114883652][ 7948900] INFO  - threddsServlet - Request Completed - 200 - -1 - 221

2013-07-22T09:21:02.376 -0600 [1114883664][ 7948913] INFO  - threddsServlet - Remote host: 68.16.167.238 - Request: "GET /thredds/catalog/nexrad/level2/KDGX/20130722/latest.xml HTTP/1.1"

2013-07-22T09:21:03.110 -0600 [1114884398][ 7948914] INFO  - threddsServlet - Remote host: 96.126.114.65 - Request: "GET /thredds/fileServer//nexrad/level3/NST/AMA/20130722/Level3_AMA_NST_20130722_0032.nids HTTP/1.0"

2013-07-22T09:21:03.128 -0600 [1114884416][ 7948914] INFO  - threddsServlet - Request Completed - 200 - 519 - 18

2013-07-22T09:21:03.174 -0600 [1114884462][ 7948915] INFO  - threddsServlet - Remote host: 96.126.114.65 - Request: "GET /thredds/fileServer//nexrad/level3/NST/HGX/20130722/Level3_HGX_NST_20130722_1515.nids HTTP/1.0"

2013-07-22T09:21:03.181 -0600 [1114884469][ 7948915] INFO  - threddsServlet - Request Completed - 200 - 525 - 7

2013-07-22T09:21:03.190 -0600 [1114884478][ 7948911] ERROR - thredds.server.wms.ThreddsWmsController - dispatchWmsRequest(): IOException:
java.io.IOException: java.lang.NullPointerException
        at thredds.server.wms.ThreddsScalarLayer.readHorizontalPoints(ThreddsScalarLayer.java:189)
        at uk.ac.rdg.resc.ncwms.controller.AbstractWmsController.readDataGrid(AbstractWmsController.java:1365)
        at uk.ac.rdg.resc.ncwms.controller.AbstractWmsController.getMap(AbstractWmsController.java:515)
        at thredds.server.wms.ThreddsWmsController.dispatchWmsRequest(ThreddsWmsController.java:179)
...
        at java.lang.Thread.run(Thread.java:722)
Caused by: java.lang.NullPointerException

2013-07-22T09:21:03.199 -0600 [1114884487][ 7948913] INFO  - threddsServlet - Request Completed - 200 - -1 - 823

2013-07-22T09:21:03.200 -0600 [1114884488][ 7948916] INFO  - threddsServlet - Remote host: 96.126.114.65 - Request: "GET /thredds/fileServer//nexrad/level3/NST/MLB/20130722/Level3_MLB_NST_20130722_1517.nids HTTP/1.0"

2013-07-22T09:21:03.200 -0600 [1114884488][ 7948903] INFO  - threddsServlet - Request Completed - 200 - -1 - 1045

2013-07-22T09:21:03.206 -0600 [1114884494][ 7948916] INFO  - threddsServlet - Request Completed - 200 - 1058 - 6

2013-07-22T09:21:03.229 -0600 [1114884517][ 7948911] INFO  - threddsServlet - Request Completed - 500 - -1 - 1000

Keep in Mind

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

In the above example, note:

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

TDS Monitoring and Debugging: Logs!

What This Section Covers

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

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