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

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:

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

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:

    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

Start of transaction

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

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:

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:

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: