Logging

During development we often add many print statements to check to see how the code is doing, what is happening, what intermediate results there are etc. When done with the development it would be nice to turn this additional code off, but have the ability to quickly turn it back on if we discover a problem. This is where logging comes into play. Logging allows us to use "rules" to say what information should be shown. For example when I am working on the code to create graphs, I do not have to see any debugging information about the SQL command being sent, however trying to figure out what goes wrong during a SQL statement it would be nice to show the SQL statements without adding any additional code.

PEcAn logging functions

These logger family of functions are more sophisticated, and can be used in place of stop, warn, print, and similar functions. The logger functions make it easier to print to a system log file.

Examples

• The file test.logger.R provides descriptive examples
• This query provides an current overview of functions that use logging
• logger functions (in order of increasing level):
  • logger.debug
  • logger.info
  • logger.warn
  • logger.error
• the logger.setLevel function sets the level at which a message will be printed
  • logger.setLevel("DEBUG") will print messages from all logger functions
  • logger.setLevel("ERROR") will only print messages from logger.error
  • logger.setLevel("INFO") and logger.setLevel("WARN") shows messages fromlogger.and higher functions, e.g.logger.setLevel("WARN")shows messages fromlogger.warnandlogger.error`
  • logger.setLevel("OFF") suppresses all logger messages
• To print all messages to console, use logger.setUseConsole(TRUE)

Related Issues (requires Redmine developer account)

• #1071 How to handle errors?
• #1222 Ignore warnings You can use @logger.setLevel("ERROR")@ to only show error messages. All the code that does not use logger will not be filtered.

Other R logging packages

• This section is for reference - these functions should not be used in PEcAn, as they are redundant with the logger.* functions described above

R does provide a basic logging capability using stop, warning and message. These allow to print message (and stop execution in case of stop). However there is not an easy method to redirect the logging information to a file, or turn the logging information on and off. This is where one of the following packages comes into play. The packages themselves are very similar since they try to emulate log4j.

Both of the following packages use a hierarchic loggers, meaning that if you change the level of displayed level of logging at one level all levels below it will update their logging.

logging

The logging development is done at http://logging.r-forge.r-project.org/ and more information is located at http://cran.r-project.org/web/packages/logging/index.html . To install use the following command:

install.packages("logging", repos="http://R-Forge.R-project.org")

futile

The second logging package is http://cran.r-project.org/web/packages/futile.logger/ and is eerily similar to logging (as a matter of fact logging is based on futile).

Example Usage

To be able to use the loggers there needs to be some initialization done. Neither package allows to read it from a configuration file, so we might want to use the pecan.xml file to set it up. The setup will always be somewhat the same:

# load library
library(logging)
logReset()

# add handlers, responsible for actually printing/saving the messages
addHandler(writeToConsole)
addHandler(writeToFile, file="file.log")

# setup root logger with INFO
setLevel('INFO')

# make all of PEcAn print debug messages
setLevel('DEBUG', getLogger('PEcAn'))

# only print info and above for the SQL part of PEcAn
setLevel('INFO', getLogger('PEcAn.SQL'))

To now use logging in the code you can use the following code:

pl <- getLogger('PEcAn.MetaAnalysis.function1')
pl$info("This is an INFO message.")
pl$debug("The value for x=%d', x)
pl$error("Something bad happened and I am scared now.")

or

loginfo("This is an INFO message.", logger='PEcAn.MetaAnalysis.function1')
logdebug("The value for x=%d', x, logger='PEcAn.MetaAnalysis.function1')
logerror("Something bad happened and I am scared now.", logger='PEcAn.MetaAnalysis.function1')