Skip to main content
Skip table of contents

Lesson - Standard Logging

This lesson teaches you the ins and outs of logging.

On completion of this lesson, participants will be able to:

  • list and set logging levels
  • instrument their code with log statements
  • filter log output in the scheme console
  • find more information about log4j

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 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.

Additional logging capabilities are available with process logging. This is an enterprise feature that allows you to instument business logic and processes beyond the base capabilities of standard logging. This is discussed in a seperate lesson.

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. Logging requests are made in scheme as:

CODE
(logger'debug "This is my log statement")

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. 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, NT 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 "%r [%t] %-5p %c - %m%n" will output something like: 176 [main] INFO org.foo.Bar - The value of x is 10. 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 of the console may be set with the following VM arguments in the Scheme Console settings... -Dlog4j.appender.console.layout.ConversionPattern=<pattern> where the pattern is something like "; %d{HH:mm:ss,SSS} %p [%c{1}] (%t) %m%n".

Instrumenting Your Code

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 <level> arg1 arg2...argN) where <level> 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 documenation on (logger... for more information. Additionally, there is a log step that make it easy to log from within services and workflows.

CODE
Example
(logger'debug) => #t ; logging at debug is enabled
(logger'debug "x =" (+ 1 2)) => "x = 3"

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:

CODE
; 09:58:44,717 DEBUG [ObjectConsumerPool] (NexJ-Worker-3) Renewing listener thread: message-puller
; 09:58:44,717 DEBUG [ObjectConsumerPool] (NexJ-Worker-13) Consumer pool received getMessage request
; 09:58:44,717 DEBUG [ObjectConsumerPool] (NexJ-Worker-7) Receiving client connection
; 09:58:44,717 DEBUG [ObjectConsumer] (NexJ-Worker-6) Deactivated ObjectConsumer@1503572282(DefaultObjectConsumerPool@1047246184(tx=false, config=ObjectConsumerConfig@1804976190(port="1111")))
; 09:58:44,717 DEBUG [ObjectConsumer] (NexJ-Worker-7) Activating ObjectConsumer@1503572282(DefaultObjectConsumerPool@1047246184(tx=false, config=ObjectConsumerConfig@1804976190(port="1111")))
; 09:58:44,717 DEBUG [ObjectConsumerPool] (NexJ-Worker-7) Renewing listener thread: socket-acceptor
; 09:58:44,717 DEBUG [ObjectConsumer] (NexJ-Worker-6) Handling request to dispatcher (3, [localhost, 60000])
; 09:58:44,718 DEBUG [ObjectQueueDispatcher] (NexJ-Worker-6) Received getMessage request from node localhost

Our default pattern layout shown above is generated with a conversion pattern of "; %d{HH:mm:ss,SSS} %p [%c{1}] (%t) %m%n"

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.

Advanced Output

Output from the standard Model Server logging can sometimes get in the way when in Debug. Console information quickly dissapears 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:

CODE
-Dlog4j.category.nexj.core.persistence=DEBUG

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 -Dlog4j.category.nexj.core.persistence.sql.

To see more categories available set your layout to -Dlog4j.appender.console.layout.ConversionPattern="; [%c] %m%n" 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:

CODE
-Dlog4j.category.nexj.core.meta.Metaclass.Person=WARN

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.

CODE
-Dlog4j.category.nexj.core.meta.integration.service.Service.MyService=DEBUG

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

CODE
-Dlog4j.category.nexj.core.meta.workflow.Workflow.MyWorkflow=DEBUG

To log activities in all workflows, enter

CODE
-Dlog4j.category.nexj.core.meta.workflow.Workflow=DEBUG

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.: Eg:

CODE
${nexj_log4j_options:INFO, file}
-Dlog4j.appender.file=org.apache.log4j.RollingFileAppender
-Dlog4j.appender.file.maxFileSize=1MB
-Dlog4j.appender.file.maxBackupIndex=5
-Dlog4j.appender.file.file="C:/work/log/out.txt"
-Dlog4j.appender.file.layout=org.apache.log4j.PatternLayout
-Dlog4j.appender.file.layout.ConversionPattern="%d{ABSOLUTE} %-5p: %m%n"

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 MyService service to that file.

CODE
-Dlog4j.appender.myappender=org.apache.log4j.RollingFileAppender
-Dlog4j.appender.myappender.maxFileSize=1MB
-Dlog4j.appender.myappender.maxBackupIndex=5
-Dlog4j.appender.myappender.file="C:/work/log/sql.txt"
-Dlog4j.appender.myappender.layout=org.apache.log4j.PatternLayout
-Dlog4j.appender.myappender.layout.ConversionPattern="%d %-5p [%c] (%t:%x) %m%n"
-Dlog4j.category.nexj.core.persistence.sql.SQLAdapter="DEBUG, myappender"
-Dlog4j.category.nexj.core.meta.integration.service.Service.MyService="DEBUG, myappender"

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".

Other Useful Categories

CODE
-Dlog4j.logger.nexj.core.hmvc.GenericView=ALL
-Dlog4j.logger.nexj.core.scripting.GlobalEnvironment=ALL
-Dlog4j.logger.nexj.core.controller.ScriptedController=ALL
-Dlog4j.logger.nexj.core.meta.Metaclass.SysCache=INFO
-Dlog4j.logger.nexj.core.meta.Metaclass.User=INFO
-Dlog4j.logger.nexj.core.rpc=INFO
-Dlog4j.logger.nexj.core.admin.etl.DataLoader=DEBUG
-Dlog4j.logger.nexj.core.persistence.sql.SQLAdapter=DEBUG

The official manual (short version) http://logging.apache.org/log4j/docs/manual.html

Good Tutorial with list of appenders http://supportweb.cs.bham.ac.uk/documentation/tutorials/docsystem/build/tutorials/log4j/log4j.html

Log4j API http://logging.apache.org/log4j/docs/api/index.html


JavaScript errors detected

Please note, these errors can depend on your browser setup.

If this problem persists, please contact our support.