Skip to content

JSoarLogging

ajsyp edited this page Nov 28, 2014 · 6 revisions

Introduction

JSoar provides a log command (and a RHS function) for writing information (strings, WMEs) to the trace and, optionally, to an SLF4J-compatible logging implementation. The log command is meant to improve and combine the echo command and the write RHS function.

Usage

Status

To view the current log settings, use: log. Text will be printed to the trace which looks like the following:

      Log Settings     
=======================
logging:           on
strict:            off
echo mode:         on
log level:         info
number of loggers: 3
------- Loggers -------
  default
* boring-logger
  exciting-logger

The default logger is always present. In this example, the user has added two additional loggers: boring-logger (which is currently disabled, as indicated by the asterisk) and exciting-logger.

Setting Parameters

The basic syntax for setting parameters with the log command is:

log --OPTION [ARGUMENT]

The table of options is listed below:

Option Arguments Description
--enable, --on, --yes Optionally, the name of a logger. If a logger name is specified, enables trace output for that logger (console output is still controlled by the specific SLF4J-compatible logging implementation). If a logger name is not specified, enables logging at a global level (including what is handled by SLF4J-compatible logging implementations). Default: logging enabled.
--disable, --off, --no Optionally, the name of a logger. If a logger name is specified, disables trace output for that logger (console output is still controlled by the specific SLF4J-compatible logging implementation). If a logger name is not specified, disables logging at a global level (including what is handled by SLF4J-compatible logging implementations). Default: logging enabled.
--add The name of a logger. Adds a new logger to the logger list. Default: only the default log is added.
--init None. Resets the logger list and set of disabled loggers (does not modify other logging options).
--strict {yes | enable | on} | {no | disable | false} Enables or disables strict mode. Default: disable.
--echo off | simple | on Changes the trace echo level. If off, log output is routed through the SLF4J-compatible logging implementation only, and trace output is disabled. If simple, logger messages are printed to the trace. If on, logger messages are printed to the trace with additional decorations (log-level of message, timestamp, and logger name). Default: on.
--level trace | debug | info | warn | error Changes the minimum log-level to display to the trace (console output is still controlled by the specific SLF4J-compatible logging implementation). Default: info.
--collapse None. Removes whitespace between log arguments (only used during an actual log command).
--source {disk | stack | none} Change which logger will be used when one is not specified. If disk is specified, the logger will be named after the file in which the current production was sourced from (if available). If stack is specified, the logger will be named after the current operator in the goal stack. If none is specified, the default logger will be used.
--abbreviate {yes | enable | on} | {no | disable | false} When the logger name is not specified, this changes whether or not the log command should try to abbreviate source locations by using only the first letter of intermediate paths. For example, path:to:file.soar versus p:t:file.soar

How to log stuff

Logging itself is straightforward. The syntax is:

log [LOGGER-NAME] LOG-LEVEL MESSAGE ...

The LOGGER-NAME is optional. If specified, it will print to the specified logger (if that logger doesn't exist, it will create it automatically--unless you are in strict mode, which will throw an exception instead); otherwise, it will auto-generate one depending on the --source setting.

The LOG-LEVEL is one of: trace, debug, info, warn, error (listed in increasing levels of logging priority). Regardless of the current log-level (set by log --level), all messages are sent to the SLF4J-compatible logging implementation (if present) with the specified log-level. The messages will also be printed to the trace if the current log-level is at or below the message's specified log-level. For example, if log --level is set to info, then only messages with LOG-LEVEL set to info, warn, or error will get printed to the trace, and the others will be silently dropped.

The MESSAGE can take several forms. If log is called as a command, then MESSAGE is just a list of strings to get printed to the log. These strings will be printed with a single space between them. To preserve spacing within strings, use quotes. No Soar-level string-substitution or pattern-matching is applied to the strings. For example, executing the following as a Soar command (in this example, is the space character):

log test-logger info I like␣␣␣␣to␣␣␣␣"program in␣␣␣␣Soar"

may produce this output:

[INFO 2014-05-21 09:45:09.436] test-logger: I like to program in␣␣␣␣Soar

On the other hand, if log is called as a RHS function, a rich feature set is available. Soar will automatically perform any pattern matching and then concatenate all strings together. For example, consider these production rules:


sp {top-state*propose*initialize
   (state <s> ^superstate nil
             -^name)
-->
   (<s> ^operator <o> +)
   (<o> ^name initialize)
}

sp {top-state*apply*initialize
   (state <s> ^operator.name initialize)
-->
   (log info |Initializing|)
}

sp {monitor*operator-application
   (state <s> ^operator.name <name>)
-->
   (log apply-operator trace |Applying operator named "| <name> |" in state | <s>)
}

After the first two decision cycles, the following log output will be generated:

[TRACE 2014-05-21 09:48:35.139] apply-operator: Applying operator named initialize in state S1
[INFO 2014-05-21 09:48:35.139] default: Initializing

Additionally, a string-substitution formatting string is allowed. For example, the previous example's "monitor*operator-application" rule could also have been written:

sp {monitor*operator-application
   (state <s> ^operator.name <name>)
-->
   (log apply-operator trace |Applying operator named {} in state {}" <name> <s>)
}

In this example, we see that the bracket pairs {} are used to indicate substitution locations. If this format is used, the number of arguments must match the number of bracket pairs (otherwise, the log messages gets processed without substitution). Moreover, only the first string has substitution applied, and all substitution arguments should follow it.

Enabling / Disabling Logging

Disabling or enabling logging controls both trace output as well as the SLF4J-compatible logging implementation; this means that if logging is disabled, nothing gets logged anywhere, period.

If performance is critical, log --disable may not be sufficient. In this case, you can use the handler RHS function to completely disable the log RHS function. To do this, run: handler --disable log. handler will disable a RHS function entirely. This means that the RHS function is short-circuited in Soar's execution logic and is never called (not even as a NOP function). If you need to enable/disable logging from a RHS function, you can use the cmd RHS function: (cmd handler --enable log).

Strict Mode

For masochistic diehards, log includes a pedantic feature called "strict mode". When strict mode is enabled, certain stream-lining behaviors are disabled. For example, if you attempt to write to an undefined logger in normal mode, log will automatically add the logger for you. In strict mode, this throws an error instead. Another example: in normal mode, disabling an undefined logger doesn't do anything, but in strict mode an exception is thrown. In strict mode, disabling an already-disabled logger throws an error, whereas in normal mode nothing exceptional happens.

The primary purpose of strict mode is to help you catch typos in your logger names. You could also use the log command to print the status of the log system and just look at the names, but maybe your logger names are getting generated dynamically and that isn't always possible.

Behavior

log can be called either as a Soar command or as a RHS function. The syntax is the same for both. Their behavior is nearly identical, the differences being:

  • When used as a RHS function, Soar will parse the arguments to log, whereas it will not do this for commands. This means that arguments to log, when used as a command, will be treated as string literals, and no pattern-matching / string-replacement will occur.