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 run time 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 instrument business logic and processes beyond the base capabilities of standard logging. This is discussed in a separate lesson.

Loggers

Loggers are typically named after the component from which they are called (for example, nexj.core.meta.Metaclass.Person). They generate log entries and follow a hierarchical 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:

SCHEME

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

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 org.apache.logging.log4j.core.layout.

The layout of the console may be set with the following VM arguments in the Scheme Console settings:

TEXT

-Dlog4j.appender.console.layout.type=PatternLayout
-Dlog4j.appender.console.layout.pattern=<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. Additionally, there is a log step that make it easy to log from within services and workflows.

For example:

SCHEME

(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 (for example, when a data source cannot be found, the message queue is unavailable, or there is a memory overflow). A sysadmin is usually paged to address the problem immediately.
Error - the application cannot continue executing a small class of requests (for example, because incorrect data has been passed from another layer, or there are service configuration problems). User errors and optimistic locking errors are reported at the Debug level instead.
Warning - potential application problem (for example, a query executes longer than a predefined threshold, there is a hacker alert, or the maximum resource pool size reached). The production systems are configured to output this level and the higher-priority levels.
Info - information about application progress (for example, configuration values, or 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 (for example, entry/exit points, user errors, recoverable errors, or 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:

TEXT

; 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

The 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 (for example, ALL may be DUMP).

Change the log level to ALL in the 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 behavior 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 statements to the VM section of the Scheme Console settings:

TEXT

-Dlog4j.logger.nexj-user-nexj-core-persistence.name=nexj.core.persistence
-Dlog4j.logger.nexj-user-nexj-core-persistence.level=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 statements to:

TEXT

-Dlog4j.logger.nexj-user-nexj-core-persistence-sql.name=nexj.core.persistence.sql
-Dlog4j.logger.nexj-user-nexj-core-persistence-sql.level=DEBUG

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 the nexj.core.meta.Metaclass. In this case, to change the log level of Person to WARN, enter the following as VM arguments:

TEXT

-Dlog4j.logger.nexj-model-class-Person.name=nexj.model.class.Person
-Dlog4j.logger.nexj-model-class-Person.level=WARN

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

TEXT

-Dlog4j.logger.nexj-model-service-MyService.name=nexj.model.service.MyService
-Dlog4j.logger.nexj-model-service-MyService.level=DEBUG

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

TEXT

-Dlog4j.logger.nexj-model-workflow-MyWorkflow.name=nexj.model.workflow.MyWorkflow
-Dlog4j.logger.nexj-model-workflow-MyWorkflow.level=DEBUG

To log activities in all workflows, enter:

TEXT

-Dlog4j.logger.nexj-model-workflow.name=nexj.model.workflow
-Dlog4j.logger.nexj-model-workflow.level=DEBUG

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 the following VM arguments:

Make sure to set the log4j.appender.rolling.fileName path appropriately for your computer.

Example:

TEXT

//Add appender to the root logger
-Dlog4j.rootLogger.appenderRef.rolling.ref=RollingFile

//Define type (also set name)
-Dlog4j.appender.rolling.type=RollingFile
-Dlog4j.appender.rolling.name=RollingFile

//Set max file size of log.  If adding one or more policies, first line must be added
-Dlog4j.appender.rolling.policies.type=Policies
-Dlog4j.appender.rolling.policies.size.type=SizeBasedTriggeringPolicy
-Dlog4j.appender.rolling.policies.size.size=1MB

//Set max number of rollover files
-Dlog4j.appender.rolling.strategy.type=DefaultRolloverStrategy
-Dlog4j.appender.rolling.strategy.max=5

//Set file location
-Dlog4j.appender.rolling.fileName=C:/work/log/out.txt

//Set pattern
-Dlog4j.appender.rolling.layout.type=PatternLayout
-Dlog4j.appender.rolling.layout.pattern=%d{ABSOLUTE} %-5p: %m%n

The appender name "fileName" 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 illustrates how the appender created in the previous section could be used to log statements from the MyService service to that file.

TEXT

//Add appender to the MyService logger
-Dlog4j.logger.nexj-model-service-MyService.name=nexj.model.service.MyService
-Dlog4j.logger.nexj-model-service-MyService.level=DEBUG

-Dlog4j.logger.nexj-model-service-MyService.appenderRef.rolling.ref = RollingFile

Run the server console and inspect the out.txt file.

Other useful categories

CODE

-Dlog4j.logger.nexj-core-hmvc-GenericView.name=nexj.core.hmvc.GenericView
-Dlog4j.logger.nexj-core-hmvc-GenericView.level=ALL

-Dlog4j.logger.nexj-model-library-audit.name=nexj.model.library.audit
-Dlog4j.logger.nexj-model-library-audit.level=ALL

-Dlog4j.logger.nexj-model-screen-SysFormHolder.name=nexj.model.screen.SysFormHolder
-Dlog4j.logger.nexj-model-screen-SysFormHolder.level=ALL

-Dlog4j.logger.nexj-model-class-SysCache.name=nexj.model.class.SysCache
-Dlog4j.logger.nexj-model-class-SysCache.level=INFO

-Dlog4j.logger.nexj-model-class-User.name=nexj.model.class.User
-Dlog4j.logger.nexj-model-class-User.level=INFO

-Dlog4j.logger.nexj-core-rpc.name=nexj.core.rpc
-Dlog4j.logger.nexj-core-rpc.level=INFO

-Dlog4j.logger.nexj-core-admin-etl-DataLoader.name=nexj.core.admin.etl.DataLoader
-Dlog4j.logger.nexj-core-admin-etl-DataLoader.level=DEBUG

-Dlog4j.logger.nexj-core-persistence-sql-SQLAdapter.name=nexj.core.persistence.sql.SQLAdapter
-Dlog4j.logger.nexj-core-persistence-sql-SQLAdapter.level=DEBUG

Additional references

The official Log4j 2 manual
Log4j API: https://logging.apache.org/log4j/2.x/manual/api.html