[Java] Log4J configuration process and broker startup behaviour

[Robbie Gemmell <ro...@gmail.com>]

The Log4J configuration sequence and its usage within the broker is in
a bit of a pickle(described below). I am wondering what people think
about how it should actually behave at startup?

Looking at the Main class from the broker suggests what it thinks is
going on is:

At startup, it checks if etc/log4j.xml exists and is readable. If it
is, it calls either DOMConfigurator.doConfigure or
DOMConfigurator.configureAndWatch depending on whether the user
requested it to watch the file for changes. If it isnt, then
BasicConfigurator.doConfigure gets called to ensure a basic console
appender is put in place. The log4j.properties file in the broker jar
is used

What is actually happening:

The main broker, common, and examples jars and the
qman(management-client) test jar have either a log4j.xml or
log4j.properties file in them. the brokers Main class has 2 statically
defined Loggers, which prompts static initialization of the log4j
LogManager class at startup, initiating scans using/of the context
classloader, class classloader, and finally the classpath first for a
log4j.xml and then for a log4j.properties file, and leading to
configuration of log4j using the first one found. Since the broker
uses qpid-all.jar in its classpath(plus anything else users add), if
any of these jars are in the lib/ dir where the broker is run [ie all
of them when running from an 'ant build', or just the broker and
common jars when starting from an 'ant release-bin' broker release
archive] then one of the defaults is found and used to configure log4j
in advance of the programmatic configuration in the brokers Main
class. Currently, running the broker out of the qpid/java/build
directory results in applying the log4j.xml file from the examples jar
before the brokers etc/log4j.xml file. If the examples jar is removed,
it moves on to the qman test jar, and then if that is removed it moves
on to the broker jars log4j.properties file. The net result is a mix
of configurations, which may or may not be exactly as expected from
the etc/log4j.xml file, depending on whether the other configuration
defined items that clash with it in some way (at the moment that
doesnt happen, but it could).

You can tell Log4J exactly which filename to use for its default
initialization configuration, or not to perform it at all. Those
options will let us fix if/when and which file is used from the jars,
eg by turning off default initialization, but doing it ourselves in a
programmatic way if required.

Further to the above, if the etc/log4j.xml file is malformed in some
way Log4J processes and applies as much of it as it can, throws out
warnings to the console when required, but then lets startup proceed
with whatever configuration it did manage to apply, meaning it is
possibly even more of a mixed configuration.  Also, if Log4J gets its
hands on a valid XML file that has an incorrect Logger Level defined
in it, it (silently !) defaults that Loggers Level to debug, and thus
also any descendant Loggers that dont have an explicit level
configured for themselves/intermediate ancestor.

To protect the broker from this, given the ability to manipulate the
etc/log4j.xml file at runtime and prompt an automated (if the
XMLWatchdog is enabled) or manual reload (via JMX), I intend to wrap
the Log4J configure and XMLWatchdog abilities with a strict parser
that will prevent the configuration process starting if any error or
warning is generated by parsing the file. I can also use the
LoggingManagement MBean to gather the Level values defined in the XML
and check they are valid, and also stop the configuration proceeding
on that basis.


Which (finally, sorry for the length of email) leads me to general
startup behaviour regarding logging configuration. What do we think is
the proper course of action to take at startup? If the etc/log4j.xml
file is missing or unreadable at the moment, the broker starts with
the fallback from (one of) the internal jar configurations. If the XML
is invalid in any way, it starts up with whatever does make it through
the configuration process, plus whatever came from the defaults inside
(one of) the jars. Should this be continued, but more strictly, so
that any issue with the XML causes use of a well defined fallback (at
startup only), or should a more firm stance be taken that the broker
wont start when an existing+readable but somehow malformed XML
configuration is present?

Robbie,
(who is off to rest his poor hands and grab lunch.)

---------------------------------------------------------------------
Apache Qpid - AMQP Messaging Implementation
Project:      http://qpid.apache.org
Use/Interact: mailto:dev-subscribe@qpid.apache.org

RE: [Java] Log4J configuration process and broker startup behaviour

[Robbie Gemmell <ro...@gmail.com>]

I updated the startup behaviour a bit when I put in the new validation
checking QpidLog4JConfigurator earlier. I added a property to the
qpid-server scripts that disables Log4J's default initialisation to stop it
wondering off and mixing configurations. The broker then checks if the
indicated XML configuration is present/readable: 

If it isn't, the properties file in the broker jar is loaded which makes the
broker default to a level according to -Damqj.logging.level (currently set
to INFO in the qpid-run script) with a basic console appender. If this
approach is considered ok I think the default should be WARN, and perhaps we
should make the properties file a more fully configured fallback.

If it is readable, then it is parsed and validated against the DTD to ensure
it generates no warnings, and then the level values specified for the
loggers in it are checked to ensure they are valid levels (Log4J will
silently default them to DEBUG if they aren't). If either of these steps
fail then the startup is aborted, causing a shutdown.

The approach is perhaps a little contradictory in that not specifying one at
all allows startup but presenting a somehow invalid configuration does not.
Should it be changed further to either shutdown in both cases, or fallback
to the properties file in both cases ?

Robbie


> -----Original Message-----
> From: Aidan Skinner
> Sent: 14 August 2009 12:02
> 
> I think failing to start is the right thing here, defaulting to
> something like debug will be too chatty and makes finding the
> origional error hard to find.
> 
> - Aidan



---------------------------------------------------------------------
Apache Qpid - AMQP Messaging Implementation
Project:      http://qpid.apache.org
Use/Interact: mailto:dev-subscribe@qpid.apache.org

Re: [Java] Log4J configuration process and broker startup behaviour

[Aidan Skinner <ai...@gmail.com>]

On Thu, Aug 13, 2009 at 2:21 PM, Robbie Gemmell<ro...@gmail.com> wrote:

> Which (finally, sorry for the length of email) leads me to general
> startup behaviour regarding logging configuration. What do we think is
> the proper course of action to take at startup? If the etc/log4j.xml
> file is missing or unreadable at the moment, the broker starts with
> the fallback from (one of) the internal jar configurations. If the XML
> is invalid in any way, it starts up with whatever does make it through
> the configuration process, plus whatever came from the defaults inside
> (one of) the jars. Should this be continued, but more strictly, so
> that any issue with the XML causes use of a well defined fallback (at
> startup only), or should a more firm stance be taken that the broker
> wont start when an existing+readable but somehow malformed XML
> configuration is present?

I think failing to start is the right thing here, defaulting to
something like debug will be too chatty and makes finding the
origional error hard to find.

- Aidan

-- 
Apache Qpid - AMQP, JMS, other messaging love http://qpid.apache.org
"A witty saying proves nothing" - Voltaire

---------------------------------------------------------------------
Apache Qpid - AMQP Messaging Implementation
Project:      http://qpid.apache.org
Use/Interact: mailto:dev-subscribe@qpid.apache.org