TDS Monitoring and Debugging: Logs!

What This Section Covers

Log! Everyone wants a log! You're gonna love it, Log!
    Come on and get your log! Everyone needs a Log!

This section covers log files generated by Tomcat and the TDS for the purposes of monitoring and debugging:

You should be familiar with Tomcat, Java, and TDS installation; as well as basic and advanced TDS configuration.

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

  1. Modify the prefix, suffix, and pattern attributes of the AccessLogValve element.
  2. 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" />
    
  3. Verify the changes to the access log have taken affect.
  4. 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:

  1. ${tomcat_home}/logs/ is where you go to look at Tomcat-generated log files; and
  2. 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 contains log messages used for debugging
serverStartup.log contains log messages from the initialization of the TDS
models.log contains log messages specific to gridded model data, especially GRIB data
cache.log contains log messages related to TDS object and file caching

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

  1. Look at the logging configurations for threddsServlet.log.
  2. 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>     
    
  3. Examine the log format being applied to the threddsServlet.log file.
  4. 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) .