Log Files Generated by the TDS

TDS Logs!

TDS Logging Directory

The log files generated by the TDS are located in the ${tds.content.root.path}/thredds/logs directory:

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.
• You may be asked to send information from threddsServlet.log to the TDS development team when seeking support.

threddsServlet.log Format

1. 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 /usr/local/tds/tomcat/webapps/thredds/WEB-INF/classes
   $ less log4j2.xml

The TDS uses the OpenSource Apache Log4J library (hence, the name of the file: log4j2.xml).

Note the PatternLayout specified for the log file format in the RollingFile entry associated with the threddsServlet log:

   <RollingFile name="threddsServlet" fileName="${tds.log.dir}/threddsServlet.log" filePattern="${tds.log.dir}/threddsServlet.%d{yyyy-MM-dd-HH}.log" immediateFlush="false">
     <PatternLayout pattern="%d{yyyy-MM-dd'T'HH:mm:ss.SSS Z} [%10r][%8X{ID}] %-5p - %c - %m%n"/>
     <Policies>
       <TimeBasedTriggeringPolicy/>
       <SizeBasedTriggeringPolicy size="100 MB"/>
     </Policies>
   </RollingFile>

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

   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 milliseconds, 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:

   2018-10-25T07:27:54.446 -0600 [   1026035][      24] INFO  - threddsServlet - Remote host: 127.0.0.1 - Request: "GET /thredds/ncml/test/H.1.1.nc?catalog=/thredds/catalog/catalog.xml&dataset=testPoint HTTP/1.1"
   

   Another way of looking at it:

   pattern	meaning	value
   %d{yyyy-MM-dd'T'HH:mm:ss.SSS Z}	Date and time	2018-10-25T07:27:54.446 -0600
   %10r	The number of milliseconds since the server was started	[ 1026035]
   %8X{ID}	Request ID	[ 24]
   %-5p	Logging level	INFO
   %c	Location in the TDS code where the message was generated	threddsServlet
   %m	Content of the log message	Remote host: 127.0.0.1 - Request: “GET /thredds/ncml/test/H.1.1.nc?catalog=/thredds/catalog/catalog.xml&dataset=testPoint HTTP/1.1”

   Note: For more information on the Log4J2 library, consult the online documentation.

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

In the above example, note:

• the request ID (7948911) appears in three locations;
• the ERROR message contains a stack trace; and
• the status code in the end of transaction message is 500 (Internal Server Error).