slf4soar

[marinier]

This idea may be a little half baked...

Background: Logging in Java

In Java, there are standard logger frameworks used to control what gets printed to the console or a file, etc. The most common frameworks are probably java.util.logging and log4j. A metalogging framework, slf4j, abstracts away the details of specific logging frameworks by providing a common wrapper around whatever logging framework you want. It has been gaining popularity.

Motivation: Logging in Soar has lots of problems

In Soar, logging is a bit more adhoc. The tutorials use RHS "write" functions, usually in separate "monitor" rules. These just write to the debugger trace. Turning off these writes means excising all the rules that write stuff.

Writing log statements in separate rules is inconvenient. SoarTech has written Tcl macros that associate each write with a logging category, and categories can be configured to be on or off. Thus, the write statements can be controlled at a finer grain and embedded directly in rules that do other things without losing the ability to turn them off. But these macros are awkward in their own way -- each rule must test one macro in the conditions, and then call another in the actions. And the level of control is not very fine.

In either case, redirecting to a file is awkward. The most common method is copy-pasting from a debugger trace into a file. If the code is embedded in an environment, something can register for the trace event and redirect it wherever. Regardless, this is harder than it should be.

Proposed solution

All of these Soar methods must be configured/handled separately from the logging in the environment code. What I propose is to expose the slf4j framework at the Soar level. Basically, we introduce a set of new RHS functions (e.g., logger.error, logger.info, etc.) obeys the slf4j configuration for the system. If a statement should be logged, it will be printed to the trace and wherever else it should go (console, file, etc.). If not, it just gets dropped. Even a pure Soar agent that just runs in the debugger could be controlled by an slf4j config file.

One of the challenges here will be associating the Soar agent's log statements with a particular component. In Java, logging can be controlled on a per-class basis -- the naive implementation would treat all logging from the agent as coming from the same class. We presumably want to be able to associate specific log statements with different parts of the agent, so we can turn different parts on and off (much like the Tcl macro solution currently does). We can have the agent pass in an extra parameter specifying the component, but I'm not sure how to associate this with something that can be controlled via the slf4j configuration. Maybe we create dummy classes via reflection that we can refer to?

[daveray]

You don't need a class to get a logger. Just use this LogFactory.getLog(String) method here. Have the agent pass the component name as the first argument and the Java code RHS function can call getLog() to pick the right logger.

Of course, it would be nice if all the rules in a file could have the same name passed auto-magically. Not sure how you could do that without tcl.

[marinier]

Awesome. We (SoarTech) will almost certainly wrap this in Tcl for two reasons:

• to automagically fill in the filename or something like that
• to make it possible to globally turn off logging for performance. That is, turn the RHS function into a comment or something so we don't pay the overhead of making the call.

[marinier]

I've been reading the slf4j docs (they are pretty sparse) -- are you suggesting using Markers to capture categories like the file name? Or is there some other API mechanism that I'm missing? The potential issue with Markers is that they are only supported by logback, so someone using a different logging framework won't get much control over the agent logging.

[daveray]

I don't know anything about markers. Here's what I was thinking off the top of my head. In soar

sp {...
->
(log info component-name |Some log message|)
}

and then in the log RHS function impl (after the args have been processed):

public void log(String level, String component, String message) {
   LogFactory.getLog(component).log(level, message);
}

Obviously, that's super-simplified, but should give you the ability to manage log levels for the "component-name" logger.

[marinier]

Ok, that makes sense. I missed that interface.

[marinier]

Do you know if it's possible to relate components in some way so if I have two components "Component1.Sub1" and "Component1.Sub2" I could turn them both on/off by referring to "Component1" (i.e., "Component1" is the parent of both of these)? Or something like that. Not a big deal if no, but it could allow finer control over the logging if yes. (As I understand, it is possible to do this with Markers, but they aren't widely supported yet, so I don't want to go there.)

[daveray]

My guess is that LogFactory.getLog(Class) just dispatches to the String version using the qualified class name, so you should get the same kind of hierarchy behavior if you structure your names like that. Just a guess though.

[marinier]

An initial version of this has been implemented. It should be pushed to this repo soon. See https://github.com/soartech/jsoar/wiki/JSoarLogging for details. It will probably evolve a bit as we actually start using it. There's a good chance this will become the defacto replacement for the RHS write function, as it has a superset of the functionality.

Also as part of this, the "handler" command has been added that allows for the disabling of any RHS function, making it very easy to do things like turn off writes to the trace, etc., which can be very helpful when trying to maximize performance without having to strip all the write statements out of the code.