A wonder-slim application logs through slf4j, like most Java code today, and needs no logging framework: out of the box, it writes its log to the console itself, with levels and a layout you set in its Properties. A logging module is only for what the console can't do, such as files, rotation and appenders. This guide covers the built-in logging, the modules, keys that configure any of them, how that combines with the configuration a Project Wonder application already has, and changing levels while the application runs.

It describes wonder-slim as of 8.1.3. Most applications never need more than the first two sections: nothing to add, and a level or two to set.

1. No logging framework needed

An application with nothing but ERExtensions logs. ERExtensions has a console logger of its own, which it uses when no logging module is on the classpath: every logger's output, WebObjects' own included, goes to the console, at the levels and in the layout of section 2. Deployed, the console is the instance's log file (section 7). The admin console's Logging page works with it, and levels can be changed on the running instance (section 4). There's no logging framework to choose, add, configure or keep up to date.

When you need more than the console, add one of two modules, which brings a logging framework as the backend:

  • ERLoggingReload4j: log4j 1.x, in its maintained form reload4j. What Project Wonder applications have always used, and the one to keep if your configuration relies on log4j's appenders.
  • ERLoggingLogback: logback, log4j's modern successor from the same author.
<dependency>
    <groupId>is.rebbi.slim</groupId>
    <artifactId>ERLoggingLogback</artifactId>
    <version>${wonder.version}</version>
</dependency>

Only one may be on the classpath. With two, the application stops at launch and names both, so if a framework you use brings ERLoggingReload4j along, exclude it from that dependency when you switch:

<dependency>
    <groupId>com.example</groupId>
    <artifactId>SomeFramework</artifactId>
    <version>1.0.0</version>
    <exclusions>
        <exclusion>
            <groupId>is.rebbi.slim</groupId>
            <artifactId>ERLoggingReload4j</artifactId>
        </exclusion>
    </exclusions>
</dependency>

A module's backend is found through Java's ServiceLoader, so there is nothing to register, and the console logger steps aside when one is there. The keys in section 2 work the same with the console logger and with both modules, so adding a module later, or removing one, changes nothing in your configuration.

Programs that don't start through ERXApplication.main() (a stand-alone tool, a batch job, unit tests) choose the console logger with a JVM option, since slf4j picks its logger before main() runs: -Dslf4j.provider=er.extensions.logging.ERXConsoleServiceProvider.

One detail you might otherwise trip over: WebObjects itself calls the log4j API in one place (encoding a direct action's query parameters), which used to mean some log4j API had to be on the classpath. wonder-slim rewrites that class at startup to log through slf4j, so it no longer does. If your own code, or a library you use, calls the log4j API, bring one yourself: with ERLoggingLogback, add log4j-over-slf4j, which hands those calls to slf4j and so to logback; ERLoggingReload4j already is one. The two can't be on the classpath together.

2. Levels and the layout

Logging is configured in the application's Properties, in keys every backend understands:

# A logger's level: TRACE, DEBUG, INFO, WARN, ERROR or OFF
er.logging.level.com.example.billing=DEBUG
er.logging.level.cayenne-sql=WARN

# The root logger's
er.logging.level.root=INFO

# The layout of the console output
er.logging.pattern=%d{MMM dd HH:mm:ss} %-5p %c - %m%n

A level applies to the logger named and everything beneath it, so er.logging.level.er.extensions covers all of ERExtensions. The level names are the same in every backend, and WARNING is read as WARN.

ERExtensions' own Properties sets the defaults: the root at INFO, and the layout above. Most applications need nothing more than a level or two of their own. The environment variants work as they do for any property, so Properties.dev is the place for what you want to see only in development:

# Properties: quiet in production
er.logging.level.cayenne-sql=WARN

# Properties.dev: every SQL statement while developing
er.logging.level.cayenne-sql=INFO

In your own code, log through slf4j as you would anywhere else:

private static final Logger log = LoggerFactory.getLogger( InvoicePage.class );

log.debug( "Rendering invoice {}", invoice.number() );

3. When configuration meets configuration

A backend can do far more than levels and a layout: files, rotation, remote targets, filters. That configuration stays available, in the backend's own form, and takes precedence where it overlaps. The whole picture is four layers, a later one winning over an earlier one where both name the same logger:

  1. Project Wonder style log4j levels: log4j.logger.X, log4j.rootLogger and log4j.rootCategory. Only for logback and the console logger, which read the levels from them (reload4j reads all of log4j.* itself, at layer 3).
  2. The keys above, er.logging.*, from wherever they're set: ERExtensions' defaults, the application's Properties, Properties.dev, the command line.
  3. The backend's own configuration: log4j.* properties for reload4j, read exactly as log4j always read them; for logback, the file the logback.configurationFile property names, or logback.xml on the classpath. If logback's configuration gives the root logger output of its own, the console output from layer 2 steps aside. The console logger has no configuration of its own.
  4. Levels set on the running instance, from the admin console or in code (section 4). These win over everything, until they're unset.

When a logger ends up at a level you didn't expect, the startup report and the admin console's Configuration page (/wonder/admin/configuration) show each property with the source it came from, and which sources it overrides.

4. Changing levels while the application runs

Logging follows the configuration: whenever a logging property changes (er.logging.*, log4j.* or logback.configurationFile), logging is configured again, and nothing else is needed. A logging property changes in three ways:

  • In development, edit the application's Properties or Properties.dev and save. The files the configuration was read from are watched, and a change is picked up within a second.
  • In deployment, files aren't watched, since much of the configuration is only read at startup. A touch file can be: set er.extensions.ERXConfigurationManager.PropertiesTouchFile to a path, and touching that file makes the application read its configuration again.
  • On a running instance, from the admin console's Configuration page ("Set a property on this instance"), or in code:
ERXConfigurationManager.setProperty( "er.logging.level.com.example.billing", "DEBUG" );

// …and back to what the configuration says
ERXConfigurationManager.unsetProperty( "er.logging.level.com.example.billing" );

A level set on the running instance wins over every other layer, the backend's own configuration included, until it's unset or the instance stops; the Configuration page marks it as set on this instance, with a button to unset it. Setting a level through the log4j API (Logger.getLogger( … ).setLevel( … )) works on reload4j only: with logback, those calls go through log4j-over-slf4j (if you have it), which can't set levels. The property works with every backend, and without one.

5. Existing log4j configuration

A Project Wonder application usually carries a block of log4j configuration in its Properties:

log4j.loggerFactory=er.extensions.logging.ERXLogger$Factory
log4j.rootCategory=INFO, A1
log4j.appender.A1=org.apache.log4j.ConsoleAppender
log4j.appender.A1.layout=er.extensions.logging.ERXPatternLayout
log4j.appender.A1.layout.ConversionPattern=%d{MMM dd HH:mm:ss} %$[%#] (%F:%L) %-5p %c %x - %t - %m%n
log4j.logger.er=INFO
log4j.logger.cayenne-sql=WARN

With ERLoggingReload4j, it keeps working unchanged: it's the backend's own configuration, layer 3.

With ERLoggingLogback, or no module at all, the levels are used (log4j.logger.* and the root's), but log4j's appenders and layouts can't be read. It names those keys in one warning at startup, and uses er.logging.pattern for its console output instead.

Converted, most of such a block turns out to repeat the defaults. The block above comes down to:

er.logging.level.cayenne-sql=WARN
er.logging.pattern=%d{MMM dd HH:mm:ss} (%F:%L) %-5p %c - %t - %m%n

The root at INFO is the default, and so is er beneath it; log4j.loggerFactory only applies to reload4j. Once converted, the configuration works with any backend, and without one. Leave the layout out entirely if the default suits you.

6. WebObjects' own output

WebObjects writes through its own NSLog. wonder-slim sends that to slf4j too, from the first line of main(), so it lands in the same log, in the same layout, with whichever backend, or none: NSLog.out to the logger NSLog at INFO, NSLog.err at WARN, NSLog.debug at DEBUG.

WebObjects writes a good deal of debug output while it starts (every one of its properties, its URLs, "Waiting for requests…"), and the startup report already says what matters of it, so it's held back: NSLog.debug reaches the log only from WebObjects' informational debug level up, and that level is capped at critical by default, whatever WebObjects' own properties say. To see the debug output, raise the cap with a JVM option (it's read before the configuration exists):

-Der.extensions.NSLog.debugLevel=2

Set er.extensions.ERXNSLogLog4jBridge.ignoreNSLogSettings=true to hand all of NSLog.debug to slf4j and decide with the NSLog logger's level instead.

7. When logging starts

Logging works from the first line of ERXApplication.main(), first to the console in the default layout, since the configuration doesn't exist yet. As soon as the configuration is composed, still in main(), logging is configured from it, before any framework initializes and before the application object is constructed. From there on, everything logged reaches the configured log: framework plugins, WebObjects' own startup, your application's constructor. The startup guide goes through the order in full.

In deployment, WebObjects sends the console to the WOOutputPath file while it constructs the application, and the console output follows it there: the console logger and logback by themselves, reload4j because wonder-slim tells it to.

8. The layout

er.logging.pattern is handed to whichever backend is in use, the console logger included, so write it in the conversions all of them understand:

ConversionGives
%d{MMM dd HH:mm:ss}the date and time, in any SimpleDateFormat pattern, or one of log4j's names for one: ISO8601 (the default), ABSOLUTE or DATE
%p, %-5pthe level, optionally padded
%cthe logger's name
%mthe message
%tthe thread
%F, %Lthe source file and line, with reload4j and logback only (the console logger writes them as they stand); fairly slow, so not for performance sensitive logging
%nthe line separator

Literal parentheses, as in (%F:%L), stay literal with all of them. Project Wonder's own additions to log4j's layout, %$ for the application's name and %# for its port, exist only in reload4j's ERXPatternLayout.

The classes behind all this are few: ERXLoggingBackend, ERXLoggingConfiguration and the console logger, ERXConsoleLoggingBackend, in ERExtensions, and one backend in each logging module. The wonder-slim repository has them, and its docs/LOGGING.md goes into the details.