This feature is available as of Armstrong Beta 0.2.

Introduction

You can control the amount of information a running LAS writes to the the Tomcat log file ($TOMCAT_HOME/logs/catalina.out) to help you determine what's going wrong when you don't get the output you expect.  By setting the logging level you can trace the progress of your request through the product server and the backend services.  The log output can also include the values of some important variables (like database connection information and SQL statements) along the way.

Logging Levels

There are five logging levels.

1. debug -- write out lots messages at each step of the process
   

2. info -- write a log message for each product request and a message when a default value is used for the resource paths (this is the default)
   

3. warn -- write out a message if something is potentially harmful, but not enough to stop a request

4. error -- write out a message when a request fails

5. fatal -- presumably used if whole web app were about to fail.  We don't use this level so setting to fatal essentially turns off all logging.

The levels are cumulative.  Setting the level causes messages from that level and above to be written to the log.  For example, the debug level gets all other message levels as well.  The warn level gets only warn, error and fatal messages.

Setting the logging level using a query parameter

When you have a request that fails, the error page should return information about the problem, including a the URL of the request that failed.  If you copy that link into your browser's address bar, add a &log_level=debug on the end of the URL and submit the URL will re-run the request with the logging level set to print out more detailed messages to the log.  Naturally, you should then look at the log to see if the additional messages give a clue as to what went wrong.

Example Log Entries

"DEBUG" level entries from a two step operation of extracting data from a database and making a plot

Each entry is marked with the name of the level so you can get an idea of what output you would get with each level you can select.  The places where the request transfers from the product server to the backend service and back have been marked in bold.  The logging level is passed to the backend service as a property, and the service logs according to the level it receives.  If no level is set the "INFO" level is used.

2007-03-21 08:40:39,171 DEBUG product.server.ProductServerAction - Entering ProductServerAction
2007-03-21 08:40:39,171 DEBUG product.server.ProductServerAction - Processing request.
2007-03-21 08:40:39,178 DEBUG product.server.ProductServerAction - Logging set to DEBUG for gov.noaa.pmel.tmap.las.product.server.ProductServerAction
2007-03-21 08:40:39,178 DEBUG product.server.ProductServerAction - Creating ProductRequest object.
2007-03-21 08:40:39,220 DEBUG product.server.ProductServerAction - Strating ProductServerRunnerthread.
2007-03-21 08:40:39,220 DEBUG product.server.ProductServerAction - Starting request by creating the ProductServerRunner.
2007-03-21 08:40:39,229 DEBUG product.server.ProductServerRunner - ProductServerRunner started.
2007-03-21 08:40:39,230 DEBUG product.server.ProductServerRunner - Use cache for all requests in this product:true
2007-03-21 08:40:39,230 DEBUG product.server.ProductServerRunner - Cache hit for all requests in this product:false
2007-03-21 08:40:39,230 DEBUG product.server.ProductServerRunner - Processing request 0 of 2
2007-03-21 08:40:39,230 DEBUG product.server.ProductServerAction - Starting ProductServerRunnerthread with timeout=20000
2007-03-21 08:40:39,230 DEBUG product.server.ProductServerRunner - Cache use is "on" for this request
2007-03-21 08:40:39,231 DEBUG product.server.ProductServerRunner - Cache hit check returned: false for request: 0
2007-03-21 08:40:39,231 DEBUG product.server.ProductServerRunner - Running backend service.
2007-03-21 08:40:39,310 DEBUG service.database.DatabaseBackendService - Logging set to DEBUG for gov.noaa.pmel.tmap.las.service.database.DatabaseBackendService
2007-03-21 08:40:39,347 INFO  las.service.TemplateTool - Setting template path to default: /home/porter/rhs/tomcat_dist/apache-tomcat-5.5.15/webapps/testbed/WEB-INF/classes/resources/database/templates/
2007-03-21 08:40:39,347 INFO  las.service.TemplateTool - Setting loader path to: /home/porter/rhs/tomcat_dist/apache-tomcat-5.5.15/webapps/testbed/WEB-INF/classes/resources/database/templates/
2007-03-21 08:40:39,367 INFO  service.database.DatabaseBackendService - Running database tool.
2007-03-21 08:40:39,368 DEBUG service.database.DatabaseTool - got db name: LAS_insitu_demo
2007-03-21 08:40:39,368 DEBUG service.database.DatabaseTool - Got driver class: com.mysql.jdbc.Driver
2007-03-21 08:40:39,369 DEBUG service.database.DatabaseTool - Got instance of driver.
2007-03-21 08:40:39,369 DEBUG service.database.DatabaseTool - About to create sqlFile
2007-03-21 08:40:39,370 DEBUG service.database.DatabaseTool - Merging sql to: /home/porter/rhs/t
omcat/webapps/testbed/output/CF7AF3C76E9495C5E9D5B8013FB72772_db_debug.txt using sql.vm
2007-03-21 08:40:39,413 DEBUG service.database.DatabaseTool - Script template merged.
2007-03-21 08:40:39,414 DEBUG service.database.DatabaseTool - Created sqlFile
2007-03-21 08:40:39,414 DEBUG service.database.DatabaseTool - preparing to read sql file
2007-03-21 08:40:39,414 DEBUG service.database.DatabaseTool - Statement ready:   SELECT CruiseNu
m,Depth,Latitude,Longitude,t,Salinity FROM Indian WHERE (Salinity<-999.0001 OR Salinity>-998.999
9) AND ((Longitude>=0.0) AND (Longitude<=129.0)) AND ((Latitude>=-75.0) AND (Latitude<=34.0)) AN
D ((Depth>=0) AND (Depth<=6500)) AND ((t>=19770101) AND (t<=19891231))
2007-03-21 08:40:39,416 DEBUG service.database.DatabaseTool - Connecting to datbase: jdbc:mysql:
//porter.pmel.noaa.gov:3306/LAS_insitu_demo?autoReconnect=true
2007-03-21 08:40:39,422 DEBUG service.database.DatabaseTool - executeQuery:   SELECT CruiseNum,D
epth,Latitude,Longitude,t,Salinity FROM Indian WHERE (Salinity<-999.0001 OR Salinity>-998.9999)
AND ((Longitude>=0.0) AND (Longitude<=129.0)) AND ((Latitude>=-75.0) AND (Latitude<=34.0)) AND (
(Depth>=0) AND (Depth<=6500)) AND ((t>=19770101) AND (t<=19891231))
2007-03-21 08:40:39,510 DEBUG service.database.DatabaseTool - Done with query.
2007-03-21 08:40:39,510 DEBUG service.database.DatabaseTool - Got netcdf filename: /home/porter/rhs/tomcat/webapps/testbed/output/CF7AF3C76E9495C5E9D5B8013FB72772_netcdf.nc
2007-03-21 08:40:39,525 DEBUG service.database.IntermediateNetcdfFile - Create new empty netCDF file.
2007-03-21 08:40:39,824 INFO  service.database.IntermediateNetcdfFile - filling netcdf file
2007-03-21 08:40:40,487 DEBUG service.database.DatabaseTool - created netcdf file
2007-03-21 08:40:40,488 DEBUG service.database.DatabaseTool - got ncml filename:
2007-03-21 08:40:40,488 DEBUG service.database.DatabaseTool - got xml filename:
2007-03-21 08:40:40,488 DEBUG service.database.DatabaseTool - finished with xml file
2007-03-21 08:40:40,497 DEBUG product.server.ProductServerRunner - Finished request 0
2007-03-21 08:40:40,497 DEBUG product.server.ProductServerRunner - Processing request 1 of 2
2007-03-21 08:40:40,497 DEBUG product.server.ProductServerRunner - Cache use is "on" for this request
2007-03-21 08:40:40,497 DEBUG product.server.ProductServerRunner - Cache hit check returned: false for request: 1
2007-03-21 08:40:40,497 DEBUG product.server.ProductServerRunner - Running backend service.
2007-03-21 08:40:40,527 DEBUG service.ferret.FerretBackendService - Logging set to DEBUG for gov.noaa.pmel.tmap.las.service.ferret.FerretBackendService
2007-03-21 08:40:40,528 INFO  las.service.TemplateTool - Setting template path to default: /home/porter/rhs/tomcat_dist/apache-tomcat-5.5.15/webapps/testbed/WEB-INF/classes/resources/ferret/templates/
2007-03-21 08:40:40,528 INFO  las.service.TemplateTool - Setting loader path to: /home/porter/rhs/tomcat_dist/apache-tomcat-5.5.15/webapps/testbed/WEB-INF/classes/resources/ferret/templates/
2007-03-21 08:40:40,539 DEBUG service.ferret.FerretTool - Running the FerretTool.
2007-03-21 08:40:40,540 DEBUG service.ferret.FerretTool - Setting up the Ferret journal file.
2007-03-21 08:40:40,540 DEBUG service.ferret.FerretTool - Creating Ferret journal file.
2007-03-21 08:40:40,542 INFO  service.ferret.FerretTool - Velocity resource path: /home/porter/rhs/tomcat_dist/apache-tomcat-5.5.15/webapps/testbed/WEB-INF/classes/resources/ferret/templates/
2007-03-21 08:40:40,561 DEBUG service.ferret.FerretTool - Finished creating Ferret journal file.
2007-03-21 08:40:40,561 DEBUG service.ferret.FerretTool - Creating Ferret task.
command line for task is:
/home/porter/tmap/ferret/x86_64-linux/bin/ferret -memsize 16 -gif -server -script FBS.jnl /home/porter/rhs/tomcat_dist/apache-tomcat-5.5.15/webapps/testbed/WEB-INF/classes/resources/ferret/temp/ferret_operation_1174495240540.jnl
2007-03-21 08:40:40,562 DEBUG service.ferret.FerretTool - Ferret task created.
2007-03-21 08:40:40,562 DEBUG service.ferret.FerretTool - Running Ferret task.
2007-03-21 08:40:41,436 DEBUG service.ferret.FerretTool - Ferret Task finished.
2007-03-21 08:40:41,436 DEBUG service.ferret.FerretTool - Checking for errors.
2007-03-21 08:40:41,437 DEBUG service.ferret.FerretTool - Creating map scale file.
2007-03-21 08:40:41,437 DEBUG service.ferret.FerretTool - Creating the index file.
2007-03-21 08:40:41,438 DEBUG service.ferret.FerretTool - Finished running the FerretTool.
2007-03-21 08:40:41,448 DEBUG product.server.ProductServerRunner - Finished request 1
2007-03-21 08:40:41,450 DEBUG product.server.ProductServerRunner - ProductServerRunner finished.
2007-03-21 08:40:41,450 DEBUG product.server.ProductServerAction - Request processed.  Preparing to return product.
2007-03-21 08:40:41,450 DEBUG product.server.ProductServerAction - Preparing the map scale file.
2007-03-21 08:40:41,451 DEBUG product.server.ProductServerAction - Preparing the range index file.
2007-03-21 08:40:41,451 INFO  product.server.ProductServerAction - Processed request: xml="<?xml version="1.0"?><lasRequest package="" href="file:las.xml"><link match="/lasdata/operations/operation[@ID='Insitu_extract_location_plot']" /><properties><ferret><view>xy</view><format>gif</format><deg_min_sec>default</deg_min_sec><expression /><image_format>default</image_format><interpolate_data>false</interpolate_data><no_margins>default</no_margins><palette>default</palette><poly_shape>default</poly_shape><size>0.5</size><use_graticules>default</use_graticules><use_ref_map>default</use_ref_map></ferret></properties><args><link match="/lasdata/datasets/Indian_Data/variables/Salinity" /><region><range low="0.0" type="x" high="129.0" /><range low="-75.0" type="y"high="34.0" /><range low="0" type="z" high="6500" /><range low="01-Jan-1977" type="t" high="31-Dec-1989" /></region></args></lasRequest>

A quick way to trace a problem

Use the URL provided to get debug output for a request that has an error

If a request you submit has an error, there will be a link on the error page for the request to the product server that failed. 

For example:

An error occurred creating your product.

Error creating the product request.

---

Link to this product.

---

java.lang.NullPointerException

An easy way to get a better idea why the request failed (particularly for an annoying failure such as this one where there is little information about what happened), copy the link location into your browser address bar and simply add &log_level=debug and resubmit the request.  Sending in the request will result in new messages in the $TOMCAT_HOME/logs/catalina.out log file that pertain to this request.  If you still can't figure out what's going on, sending these log messages to the LAS team might be a good way for us to get started debugging your problem.