MS RFC 28: Redesign of LOG/DEBUG output mechanisms

Date:

2007-06-14

Author:

Daniel Morissette

Contact:

dmorissette at mapgears.com

Last Edited:

2007-08-24

Status:

Adopted (2007-06-29) - Implementation completed (2007/07/06)

Version:

MapServer 5.0

Overview

MapServer 4.10 and older used to have multiple LOG/DEBUG output mechanisms that did not play well together. In order to improve the usability of the software this RFC proposes a new LOG/DEBUG output mechanism with more control on the output location (logfile or stderr) and that works under all supported web servers.

Inventory of existing mechanisms

MapServer 4.10 and older support the following LOG/DEBUG systems:

• LOG [filename] in the WEB object:

  From the documentation: “File to log MapServer activity in. Must be writable by the user the web server is running as.”

  More specifically, the function writeLog() in mapserv.c logs information about the mapserv CGI request results at the end of its execution. This option has no effect with MapScript.

• MS_ERRORFILE environment variable:

  If set then all calls to msSetError() are logged to this file.

• msDebug() with DEBUG ON/OFF at the MAP and LAYER level:

  There are msDebug() calls in various areas of the code that generate information that may be useful in tuning and troubleshooting apps. The DEBUG ON/OFF statements in the MAP and LAYER objects are used to enable/disable the msDebug() calls. The msDebug() mechanism is also disabled by default and enabled only by the -DENABLE_STDERR_DEBUG compile-time option. Users could benefit from easier access to this and more debug information.

  The output of msDebug() is sent to stderr and cannot be redirected. In addition to not being very flexible, this is a problem under IIS where stderr output goes to stdout and the msDebug() output corrupt MapServer’s output.

Questions

• Q: Is the mapserv-specific LOG option really used by anyone? Do we need to maintain it, should we get rid of it, or perhaps extend it? At a minimum this option should be better documented to avoid confusion with the other mechanisms described in this RFC.

  A: The LOG option will be left untouched by this RFC.

Technical Solution

We will essentially merge the MS_ERRORFILE and DEBUG/msDebug() mechanisms. The variable MS_ERRORFILE will specify the location of the output, with possible values being either a file path on disk, or one of “stderr” or “stdout”.

The current DEBUG ON/OFF mechanism that controls msDebug() output will also be extended to support multiple DEBUG levels.

In order to keep the implementation relatively simple and efficient, the output file handle will be kept open with a reference to it in a global variable in the context of the current request and will be closed only in msCleanup(). This means that if two mapfiles are loaded in the same request with different MS_ERRORFILE settings then errors/debug statements for both will go to the same file (and the output file will change when the second mapfile is read).

Note: the output file handle will be global in the context of the current request only and not global across threads, this will be done using the same mechanism currently used by msGetErrorObj() in maperror.c.

Setting MS_ERRORFILE

The variable MS_ERRORFILE will specify the location of the output, with possible values being either a file path on disk, or one of the following special values:

• “stderr” to send output to standard error. Under Apache stderr is the Apache error_log file. Under IIS stderr goes to stdout so its use is discouraged. With IIS it is recommended to direct output to a file on disk instead.

• “stdout” to send output to standard output, combined with the rest of MapServer’s output

• “windowsdebug” to send output to the Windows OutputDebugString API, allowing the use of external programs like SysInternals debugview to display the debug output.

It will be possible to specify MS_ERRORFILE either as an environment variable or via a CONFIG directive inside a mapfile:

CONFIG  "MS_ERRORFILE" "/tmp/mapserver.log"

or

CONFIG  "MS_ERRORFILE" "stderr"

If both the MS_ERRORFILE environment variable is set and a CONFIG MS_ERRORFILE is also set, then the CONFIG directive takes precedence.

If MS_ERRORFILE is not set then error/debug logging is disabled. During parsing of a mapfile, error/debug logging may become available only after the MS_ERRORFILE directive has been parsed.

DEBUG levels

The current DEBUG ON/OFF mechanism, at the layer and map level will be extended to support multiple debug levels as follows. The default is DEBUG OFF (Level 0):

• Level 0: Errors only (DEBUG OFF, or DEBUG 0)

  In level 0, only msSetError() calls are logged to MS_ERORFILE. No msDebug() output at all. This is the default and corresponds to the original behavior of MS_ERRORFILE in MapServer 4.x

• Level 1: Errors and Notices (DEBUG ON, or DEBUG 1)

  Level 1 includes all output from Level 0 plus msDebug() warnings about common pitfalls, failed assertions or non-fatal error situations (e.g. missing or invalid values for some parameters, missing shapefiles in tileindex, timeout error from remote WMS/WFS servers, etc.)

• Level 2: Map Tuning (DEBUG 2)

  Level 2 includes all output from Level 1 plus notices and timing information useful for tuning mapfiles and applications

• Level 3: Verbose Debug (DEBUG 3)

  All of Level 2 plus some debug output useful in troubleshooting problems such as WMS connection URLs being called, database connection calls, etc.

• Level 4: Very Verbose Debug (DEBUG 4)

  Level 3 plus even more details…

• Level 5: Very Very Verbose Debug (DEBUG 5)

  Level 4 plus any msDebug() output that might be more useful to the developers than to the users.

The MS_DEBUGLEVEL environment variable

Debug level can also be set using the (optional) MS_DEBUGLEVEL environment variable.

When set, this value is used as the default debug level value for all map and layer objects as they are loaded by the mapfile parser. This option also sets the debug level for any msDebug() call located outside of the context of a map or layer object, for instance for debug statements relating to initialization before a map is loaded. If a DEBUG value is also specified in the mapfile in some map or layer objects then the local value (in the mapfile) takes precedence over the value of the environment variable.

This option is mostly useful when tuning applications by enabling timing/debug output before the map is loaded, to capture the full process initialization and map loading time, for instance.

MapScript Implications

No direct implication. Setting MS_ERRORFILE will enable debug output in MapScript as well.

Note that output to stderr or stdout may not work as expected in some scripting environments and we do not plan to make any special efforts to support those special cases as part of this RFC. However, logging to a file on disk will work with all MapScript flavours.

Files affected

map.h
mapfile.c
maperror.c

Several source files with msDebug() calls in them may also need to be edited to adjust the debug level at which the various msDebug() calls kick in.

Backwards compatibility issues

• The MapServer 4.x and older MS_ERRORFILE continues to work as before by default

• The DEBUG ON/OFF mechanism continues to work as before. However some msDebug() output from previous versions of MapServer may require a higher debug level in order to be enabled.

Bug ID

• 709: https://github.com/MapServer/MapServer/issues/709

• 1333: https://github.com/MapServer/MapServer/issues/1333

• 1783: https://github.com/MapServer/MapServer/issues/1783

• 2124: https://github.com/MapServer/MapServer/issues/2124

Voting history

Vote completed on 2007-06-29:

+1 from DanielM, TomK, FrankW, TamasS, JeffM, SteveL and AssefaY.

Questions/Comments from the review period

• Q: Can we catch the output of OGR/GDAL’s CPLDebug calls, perhaps when the map-level debug level is >= 3?

  A: Frank suggests that we keep this for a later phase.