Getting Control of Your Console Logger

In this article, I’ll provide details on the ins and outs of our console logger. It is an except from some upcoming intermediate training material. We will discuss some key concepts, instrumenting your code, setting log levels, and some advanced output options.

Key Concepts
Standard logging provides visibility into the activities of the running system over time. The model should log sufficient information to facilitate debugging and problem identification. NexJ’s platform provides:

• Flexible control over the level-of-detail that is logged
• Code instrumentation with the logger function
• Flexible output options and filtering

NexJ integrates with log4j. Log4j has three main components: loggers, appenders and layouts. These allow you to log messages according to type and level, and to control at runtime how these messages are formatted and where they are reported. Configuration of the log4j environment is typically done at application initialization from a configuration file or VM arguments, although there is an interesting article on the community about Setting the log level in a running console. There are other ways of looking into your running code, such as process logging and statistics/monitoring, but those will be discussed in other articles.

So, let’s talk about Loggers, Appenders, and Layouts…

Loggers
Loggers are typically named after the component from which they are called. e.g. nexj.core.meta.Metaclass.Person. They are what generate log entries. They follow a hierachical naming rule. For example, the logger named “nexj.core” is a parent of the logger named “nexj.core.meta”. Parents will output all logs generated by their children. In another example, “java” is a parent of “java.util” and is an ancestor of “java.util.Vector”. There is a special root logger that always exists.

For our purposes, loggers may be assigned the following orders: dump, debug, info, warn, error and fatal. Levels are ordered where dump < debug < info < warn < error < fatal.

These logging requests are made in scheme as:

The logger function’s printing methods – dump, debug, info, warn, error, and fatal – determine the output level of a logging request. A logging request is enabled and will be printed if its level is higher than or equal to the current logging level of the running server. Otherwise, the request is disabled and will not be printed.

Appenders
An output destination for log statements is called an appender.  Appenders can be configured for the console, files, GUI components, remote socket servers, JMS, Mail Systems, Windows Event Loggers, and remote UNIX Syslog daemons.  It is also possible to log asynchronously. Loggers may output to multiple appenders. Each appender may have it’s own layout. By default the Server Console outputs to the console.

Layouts
PatternLayouts let you specify output formats.  For example, a PatternLayout with the conversion pattern

will output something like:

where the first field is the number of milliseconds elapsed since the start of the program. The second field is the thread making the log request. The third field is the level of the log statement. The fourth field is the name of the logger associated with the log request. The text after the ‘-‘ is the message of the statement. Pattern options can be found at

http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/PatternLayout.html

The layout for the NexJ Studio console may be set with the following VM arguments in the Scheme Console settings (in the Run Scheme Console/Scheme Console Settings toolbar item or the Window/Preferences… NexJ Studio/Launch Settings/Scheme Console menu item).

where the pattern is something like

Instrumenting Your Code with the logger function
NexJ’s Model Server is already instrumented with logging statements. These statements will be output if they are enabled which depends on the server’s current logging level.

You may instrument your script using (logger arg1 arg2…argN) where arg1 is one of ‘fatal, ‘error, ‘warn, ‘info, ‘debug or ‘dump. It prints its arguments separated by spaces. The arguments are evaluated only if the corresponding log level is enabled. See the documentation on (logger… for more information. Additionally, there is a log step that make it easy to log from within services and workflows.

Example

Code should use the Logger methods corresponding to individual logging levels as follows:

• Fatal – the application cannot execute any request, e.g. data source cannot be found, message queue is unavailable, memory overflow. A sysadmin is usually paged to address the problem immediately.
• Error – the application cannot continue executing a small class of requests, e.g. incorrect data has been passed from another layer, service configuration problems. User errors and optimistic locking errors are reported at the Debug level instead.
• Warning – potential application problem, e.g. a query executes longer than a predefined threshold, hacker alert, maximum resource pool size reached. The production systems are configured to output this level and the higher-priority levels.
• Info – information about application progress, e.g. configuration values, service startup/shutdown. The amount of the logged information is not proportional to the number of handled requests. If it is proportional, use Debug level instead.
• Debug – detailed debugging information that can be used for identifying problems without a debugger, e.g. entry/exit points, user errors, recoverable errors, algorithm steps. The logged messages usually do not exceed 255 characters. The application performance is significantly reduced when this logging level is enabled. Not for production use.
• Dump – dump of object state for very detailed debugging. The log files will grow rapidly.

These statements may be placed anywhere in your code.

Setting Log Levels

To see logging in action, start the server console in NexJ Studio. You should see log statements as the model server starts up and loads the model.  By default the output looks something like:

Note: Our default pattern layout shown above is generated with a conversion pattern of

Stop the console. From the Run Scheme Console toolbar drop-down menu, select Scheme Console Settings. You will see the Scheme Console Settings dialog with the Default Log Level and Common VM Arguments. Notice you can set the level and arguments specifically for any of the console types or globally. Supported levels for the server are ERROR, WARN, INFO, DEBUG and ALL, where ERROR is the least verbose and ALL is the most. Different servers may have different names for these levels e.g. ALL may be DUMP. Change the log level to ALL in preferences/Scheme Console Settings and restart the server. You will see much more output.

For information on configuring logging in different containers, see:

• JBoss – http://docs.jboss.org/process-guide/en/html/logging.html . Usually done using conf/jboss-log4j.xml file.
• Websphere – http://publib.boulder.ibm.com/infocenter/wasinfo/v7r0/index.jsp?topic=/com.ibm.websphere.express.doc/info/exp/ae/rtrb_enabletrc.html

Advanced Output
Output from the standard Model Server logging can sometimes get in the way when in Debug. Console information quickly disappears into the past because queues and timers are firing and logging activity from integration and the database. Sometimes more advanced control over the behaviour of the logger is desirable.

Filtering with Categories

Log statements are categorized by source. All Model Server categories begin with “nexj.core”.  Some useful categories include:

• integration
• meta
• monitoring
• persistence
• rpc
• runtime
• scripting

Categories allow you to set different log options for different loggers. For example, if you only want to log output from the persistence layer at DEBUG level, set the console to INFO level and add the following statement to the VM section of the Scheme Console settings:

This will enable all log statements at INFO or above but will enable nexj.core.persistence.* log statements at DEBUG  or above.  To more specifically log only database persistence, change the statement to

To see more categories available set your layout to

and run the server console. You may specify the category at any level from “nexj” all the way down to very specific components e.g. nexj.core.persistence.sql.SQLHook

Logging Specific Metadata
It’s possible to specify logging down to the metadata level.  For example classes may be specified in categories by appending the metadata class name to nexj.core.meta.Metaclass. In this case, to change the log level of Person to WARN enter the following as a VM argument:

The same concept may be applied to integration services and business model workflows. To log activities in a service called MyService at DEBUG level, enter the following as a VM argument.

To log activities in a workflow called MyWorkflow at DEBUG level, enter the following as a VM argument to the server console settings.

To log activities in all workflows, enter

To log all activities in the workflow engine, use nexj.core.meta.workflow as the category. As you can see the logger offers very fine control over the breadth and scope of the level of information to output to the logs.

Logging Server Console Output to a File
To write the console output to a file, add these VM arguments (make sure to set the log4j.appender.file.file path appropriately for your computer). The statement ${nexj_log4j_options:INFO, file} attaches all output at INFO level to the file appender.:

example

Note: The appender name “file” in the above example could be any other name and the example would work the same.

Logging messages from specific loggers in separate log file 

Log statements for specific loggers can be logged into a separate file by creating an appender and associating a specific logger with it.  The code below creates a rolling file appender called myappender and logs statements from the SQLAdapter and the MyService service to that file.

Run the server console and look in the sql.txt file.

To log from a specific service to a specific appender you would enter a line like

-Dlog4j.category.nexj.core.meta.integration.service.Service.MyService=”DEBUG, myappender”.

In a JBoss log4j.xml file this configuration would look like:

Now specify the log level (priority value) and the logger file for the MyService logger.

Other Useful Categories

Wrapup

There is a lot of flexibility and power in the Model Server’s logging capabilities.  If anyone has any other helpful info on logging, please add a comment to this article.

Until next time, Ed