Project

General

Profile

Logging

Whether you are investigating an issue in FWD runtime code or in business logic, a well-placed logging statement can be a low impact mechanism to look inside the state of your application or the runtime environment. Logging statements should be added with careful consideration for performance impacts and readability of the resulting log information.

The FWD server environment supports “proper” logging, by which we mean that a logging infrastructure based on the J2SE logging environment is available to the developer. The FWD client runtime code base, on the other hand, does not offer this facility, though it is expected to be added with future development.

“Poor Man's” Logging

In the absence of a true logging infrastructure, or when a temporary solution is more appropriate or simply more convenient, basic print or println statements serve as a handy backup method of dumping runtime information. Currently, this is the only form of logging currently available for the FWD client runtime code base.

The current version of FWD supports the character mode user interface (CHUI) as an interactive client. This implementation uses the terminal's stdout stream to render its user interface, so calls to System.out.println for example, are not recommended in the client code base, as they will cause screen corruption which likely will get in the way of any debugging efforts. Rather, use System.err as the target stream, and redirect the terminal's stderr stream to a file when launching the FWD CHUI client, as in:

java {JVM options} com.goldencode.p2j.main.ClientDriver {program options} 2>client.log

The use of System.out.println and System.err.println for temporary debug logging statements is naturally supported on the FWD server as well, and sometimes this is the best option to gather ad-hoc information. This is a particularly good option for performance-sensitive areas, where the overhead of logging decisions is undesirable, and you do not want to leave a permanent logging statement behind in the code. Of course, it is very important to remove any such statements after a debugging effort is complete.

“Proper” Logging

The foundation of logging in the FWD (server) environment is the logging infrastructure added to the Java platform in J2SE 1.4, the public API for which is in the java.util.logging package. This package contains the Logger class, instances of which are worker objects used to log messages for specific system or application components. Logger instances can be named or anonymous:

  • named loggers are named using a dot-separated, hierarchical namespace, which typically corresponds with a specific package or class name. Named loggers in FWD runtime code follow this convention.
  • anonymous loggers have no associated namespace, and as such, cannot be retrieved by name. Thus, an anonymous logger, once obtained, can only be accessed by the object reference first returned by the logging environment. Thus, access to it can be protected, so that unrelated code cannot retrieve it and change its state. This is an important security consideration, as it prevents an untrusted piece of code from obtaining the logger by name and affecting the integrity of security sensitive logging, such as audit messages, for example.

Log messages are each assigned a level of severity which are constants of the Level class. The following mappings are used to convert a symbolic string in the directory (the server's primary configuration file) into a Level constant. This table is in order of least verbose logging to most verbose logging:

Configuration Value Logging Level
OFF Level.OFF
SEVERE Level.SEVERE
WARNING Level.WARNING
INFO Level.INFO
FINE Level.FINE
FINER Level.FINER
FINEST Level.FINEST
ALL Level.ALL

These are checked against configuration values associated in the FWD directory with the names of individual Logger instances, and against global settings for various types of log handlers. This check determines whether a given log message is recorded/displayed or not.

Search Algorithm

FWD can lookup settings from the storage using a Unix - filesystem like path strings. A key resembles to leaf/file in the xml structure of the directory file. There are two cases:

  • if the value is a fixed path from the root of the directory then it is an absolute path and there is no search process, the value is looked-up directly
  • any other string that can be located in different root paths is a relative path which can be searched using the algorithm briefly described in the following paragraphs.

The directory will usually contain at least one "logging" section, however the defaults set below will take effect if there is no such section. The configuration is normally found via the path /server/default/logging and in that case it defines the default values for all servers. A given server can have a more specific or custom logging configuration by adding the section via the path /server/[serverid]/logging where [serverid] is the unique server account name for the server being configured. The search algorithm described “Directory” chapter is responsible to look for the appropriate value:

  • the server-specific path is searched first and if found it is honored,
  • otherwise the default path is searched and honored if found,
  • if no logging configuration is found at all, the defaults will be used.

Although J2SE supports pluggable handlers and formatters, only console and file handler types are supported at this time. Likewise, user-defined formatters are not supported. FWD uses its own custom formatter that displays state from the current session and thread's context. Each log entry will look like the following in the case that the message was output from a server thread that does not have an end-user context:

[09/10/2012 14:34:42 EEST] (SecurityManager:FINE) {main} Loaded CA   cert of Certificate Authority

In the case that the message is logged from a thread that has an end-user context, the message would look like this:

[09/10/2012 14:34:43 EEST] (SessionManager.listen():INFO) {00000000:00000001:standard} Server ready

In both cases, the first section, delimited by square brackets is the date / timestamp of the event.

Likewise, both will have a second section with the class name of the source of the message and the message level, delimited by normal parenthesis.

The portion with curly braces is either a {thread_name} or user context data. The user context data is in the format {session_id:thread_id:user_id}. The first component, 00000000, is the unique session ID which the FWD Security Manager has assigned to the user session from which the message is logged. The second component, 00000001, is the unique thread ID, also assigned by the Security Manager. Both the session ID and thread ID are formatted as eight-digit hexadecimal strings. The third component, standard, is the user name associated with the session. The same user name may be associated with multiple sessions and threads at the same time; this indicates the user has multiple client sessions active with the FWD server.

The main content of the log entry follows the curly braces.

Example

The following is an example of the most common logging settings.

GES: Please examine the code in FWD that uses these values and add any additional values to the reference table below that are not listed here, but which are related.

<node class="container" name="logging">
   <node class="string" name="level">
      <node-attribute name="value" value="WARNING"/>
   </node>
   <node class="container" name="loggers">
      <node class="string" name="com.goldencode.p2j.net">
         <node-attribute name="value" value="INFO"/>
      </node>
      <node class="string" name="com.goldencode.p2j">
         <node-attribute name="value" value="WARNING"/>
      </node>
      <node class="string" name="com.goldencode.p2j.persist">
         <node-attribute name="value" value="INFO"/>
      </node>
      <node class="string" name="org.hibernate">
         <node-attribute name="value" value="WARNING"/>
      </node>
      <node class="string" name="org.hibernate.jdbc">
         <node-attribute name="value" value="SEVERE"/>
      </node>
         <node class="string" name="org.hibernate.cache">
         <node-attribute name="value" value="SEVERE"/>
      </node>
   </node>
   <node class="container" name="handlers">
      <node class="container" name="console">
         <node class="string" name="level">
            <node-attribute name="value" value="FINEST"/>
         </node>
      </node>
      <node class="container" name="file">
         <node class="integer" name="limit">
            <node-attribute name="value" value="64"/>
         </node>
         <node class="boolean" name="append">
            <node-attribute name="value" value="FALSE"/>
         </node>
         <node class="string" name="level">
            <node-attribute name="value" value="FINEST"/>
         </node>
         <node class="string" name="pattern">
            <node-attribute name="value" value="server_%s_%g.log"/>
         </node>
         <node class="integer" name="count">
            <node-attribute name="value" value="4"/>
         </node>
      </node>
   </node>
</node>

Useful General Purpose Logging

When all else fails, logging can be a useful fall-back plan. The reason one doesn't usually start with logging is that the output from logging can be quite voluminous and thus very time consuming to interpret.

Please see the section above on the logging facilities built into the runtime. These facilities would be used to configure each server's logging settings. After changing any of the directory configuration for logging, the server will need to be restarted for those settings to take effect.

The following classes have highly useful, general purpose logging implemented:

Class Best Logging Level Output
com.goldencode.p2j.util.TransactionManager FINE This will provide a log entry on every block related event and the block's current state at the time of the event. Events include entering a block, iterating a block, retrying a block and exiting a block.
com.goldencode.net.RemoteObject FINER Provides a log entry for every outbound remote call.
com.goldencode.net.RemoteObject FINEST In addition to the output from FINER level (see above), this provides a dump of the remote call parameters and a log entry (including the elapsed time) for when the remote call completes.
com.goldencode.net.Dispatcher FINER Provides a log entry for every inbound remote call.
com.goldencode.net.Dispatcher FINEST In addition to the output from FINER level (see above), this provides a dump of the remote call parameters and a log entry (including the elapsed time) for when the call completes.

Since the FWD remote object protocol is bi-directional (the client can call the server and the server can call the client), it is usually important to implement RemoteObject logging (to see outbound calls) in conjunction with Dispatcher logging (to see inbound calls). The combination allows the developer to see all protocol traffic.

Apache Commons Logging

In certain classes (notably in the com.goldencode.p2j.persist package and its sub-packages) a different logging mechanism is employed, though it is configured in the same way, and is backed by the same logging infrastructure.

This logging mechanism uses the Apache Commons logging classes, an open source library available at http://commons.apache.org/logging/. This library is designed to sit atop various Java logging infrastructures, such as Log4J or - as is the case with the FWD runtime environment - the J2SE logging libraries. Additional implementations are supported. The intention is to provide a uniform logging interface for a developer's use, regardless of the underlying logging implementation.

The use of different logging approaches in different parts of the FWD runtime is historical and the intention is to phase out the use of the Apache Commons logging library in future versions of the FWD Project.

The process of retrieving a logging object and using that object to write log messages with the Apache Commons library is conceptually the same as the examples shown above, but the API is a bit different.

The Apache Commons logging library defines its own constants for the various logging levels, which map to the J2SE logging levels as follows:

Apache Commons Logging Level J2SE Logging Level
FATAL SEVERE
ERROR SEVERE
WARN WARNING
INFO INFO
DEBUG FINE
TRACE FINEST

Note there is no Apache Commons analog for the J2SE logging level of FINER. The TRACE level includes both the FINER and FINEST levels.

Because this logging mechanism is targeted for removal in future versions of the FWD Project, it may not occur in newest code. Nevertheless, it is shortly described here so that readers will understand its use.

Changing Logging Levels

Currently, there is no support for dynamic changes to the logging levels of individual loggers, nor to the default logging settings for the FWD server as a whole. In order to change logger settings today, the server must be stopped, the logging configuration changed in the FWD server directory, and the server must then be restarted.

This limitation may be removed in a future version of the FWD Project.

Reference

The following options can be specified:

Option ID Data Type Default Value Required Details
level string WARNING No This specifies the logging level for any otherwise unconfigured handlers. Note that at this time, additional handler support is not provided or used in FWD.
handlers/console/level string WARNING No The logging level for the console handler. This will limit all log output via the console to this level and above. All of this console output will be written to the server process' STDERR.
Warning: no matter what logging level the logger (see below) is set to, only log entries of equivalent or less verbosity will be allowed to emit on this handler. Thus this logging level is a filter to exclude content that has been created by one or more loggers.
handlers/file/level string OFF No The logging level for the file handler. This will limit all log output via the file to this level and above.
Warning: no matter what logging level the logger (see below) is set to, only log entries of equivalent or less verbosity will be allowed to emit on this handler. Thus this logging level is a filter to exclude content that has been created by one or more loggers.
handlers/file/append boolean FALSE No TRUE will append to the file handler's previous log file, FALSE will overwrite.
handlers/file/limit integer 8 No Maximum file size for each log file in megabytes for the file handler.
handlers/file/pattern string %h/p2j_server_%s_%g.log No File name pattern for the file handler. The following macros can be used:
     %h is the current user's home directory,
     %s is the server account name,
     %g is a generation number.
handlers/file/count integer 4 No Number of log file generations for the file handler.
loggers/<logger_name>/level string n/a No The logging level for any arbitrary logger name (in a hierarchical namespace). By convention, the namespace is based on the package/class name hierarchy. This is not required since any arbitrary text can be inserted. However, FWD does use the package and optionally the class name when creating loggers. If these loggers have a name that begins with at least one of the specified logging levels in this section, the most specific (longest) matching name will specify the logging level for that logger. There may be any number of these entries. As a result, one may specify the logging level for a specific package (and by default all contained classes and sub-packages and their classes). In addition, a more specific class or package name will override the "parent" logging level with the one specified in that more specific entry.
This sets the level for the source of a log message. That means that the class that is logging will only log messages at that level (and all less verbose levels). But the handler's (the output destination for loggers) logging level (which is set separately) may exclude the generated messages if the handler's logging level is less verbose than that of the logger being used.

© 2004-2017 Golden Code Development Corporation. ALL RIGHTS RESERVED.