A Tangled Web

Component Loggers in Open ESB

Extensive logging capabilities are available in Open ESB 2.0 to help a component developer diagnose problems within a component. This discussion describes what logging facilities are available and how to control the levels of the various loggers.

Obtaining Component Loggers

The JSR208 specification requires the JBI runtime to provide a way for JBI components (Binding Components and Service Engines) to obtain loggers at runtime. The getLogger() method provided by the javax.jbi.component.ComponentContext interface should be used by components to obtain their loggers. The method is defined as follows in the JSR208 specification:

     getLogger(String, String)

public java.util.logging.Logger getLogger(java.lang.String suffix,
    java.lang.String resourceBundleName)
    throws MissingResourceException, JBIException

Get a logger instance from JBI. Loggers supplied by JBI are guaranteed to have unique names such that they avoid name collisions with loggers from other components created using this method. The suffix parameter allows for the creation of subloggers as needed. The JBI specification says nothing about the exact names to be used, only that they must be unique across components and the JBI implementation itself.

Parameters:

suffix - for creating subloggers; use an empty string for the base component logger; must be non-null.

resourceBundleName - name of ResourceBundle to be used for localizing messages for the logger. May be null if none of the messages require localization. The resource, if non-null, must be loadable using the component's class loader as the initiating loader.

Returns:

a standard logger, named uniquely for this component (plus the given suffix, if applicable); must be non-null.

Throws:

java.util.MissingResourceException - if the resourceBundleName is non-null and no corresponding resource can be found.

javax.jbi.JBIException - if the resourceBundleName has changed from a previous invocation by this component of this method with the same suffix.

Runtime Support for Component Loggers

In the Open ESB 2.0 implementation, the following implementation characteristics are provided to facilitate the use of component loggers, when the loggers are obtained using the getLogger() method provided by the javax.jbi.component.ComponentContext interface:

• All component loggers have names prefixed with the component name to guarantee uniqueness across the entire JBI runtime, as required by the JSR208 specification. For example, if a component with a name "my-binding" requests a logger called "com.acme.binding.LifeCycle", the actual logger name will be set to "my-binding.com.acme.binding.LifeCycle".
• If several components share common code, and the common code is designed to use the ComponentContext to obtain loggers, each component will get its own set of loggers for the common code. This allows the log levels for the common code to be controlled on a per-component basis to facilitate debugging a single component without the added burden of extra logging from other components.
• For every component, the runtime automatically creates a top-level logger with the logger name equal to the component name. All loggers created for the component using the ComponentContext.getLogger() method inherit their log levels from the top-level logger until they are explicitly set to another level. This allows setting a global log level for the entire component by setting the level of the top-level logger.
• For every component, the runtime creates a logger MBean that keeps track of the loggers for that component. This MBean provides operations to get and set the levels of those loggers, and an operation to get a list of all loggers requested by the component.
• Logger level settings for a component are persisted by the logger MBean so that they are restored after a restart of the JBI runtime.
• Loggers for a component may be pre-declared through an extension of the installation descriptor in the jbi.xml for the component. This allows the levels of the component loggers to be set even before the component has been started for the first time after installation.
• A logger level inheritance mechanism is provided for convenience when setting logger levels.
• A shortened "display name" can be set in the installation descriptor extension and is saved by the runtime. If a display name is not provided, it defaults to the last level of the logger name.
  

Component Logger Level Inheritance

In order to facilitate controlling the levels of component loggers, the runtime provides for logger level inheritance. There is a main logger for the entire JBI runtime called com.sun.jbi. When the runtime creates the top-level logger for a component, as described in the previous section, that logger's level is set to null and it inherits its level from the com.sun.jbi logger until the logger's level is explicitly set. Likewise, when the runtime creates any logger for a component as a result of a call to ComponentContext.getLogger(), that logger's level is set to null and it inherits its level from the top-level component logger until its level is explicitly set. After any logger's level has been explicitly set, that level is persisted across restarts of the JBI runtime, and restored when the logger is created again. Once a logger's level has been explicitly set, the only way to make it revert to inheriting its level from its parent logger is to use the admin console to set the level to "DEFAULT" using the pull-down list of logger levels. This sets the actual level of the logger back to null, causing it to once again inherit its level from its parent logger.

Pre-Declaring Component Loggers

If you want to pre-declare the loggers for a component, you must do two things. First, you must declare the namespace URI for the logging extension in the installation descriptor contained in the jbi.xml file for the component. Add the following namespace URI:

xmlns:logging="http://www.sun.com/jbi/descriptor/logging"

Second, you must add the the logging extension, with component logger names that your component requests through the ComponentContext.getLogger() method, to the installation descriptor, in the <component> section:

        <logging:Logging>
            <logging:logger displayName="ACME Binding life cycle">com.acme.binding.LifeCycle</logging:logger>
            <logging:logger displayName="ACME Binding messaging">com.acme.binding.Messaging</logging:logger>
            <logging:logger displayName="ACME Binding deployment">com.acme.binding.Deployment</logging:logger>
            <logging:logger displayName="ACME Binding utilities">com.acme.binding.Util</logging:logger>
        </logging:Logging>

When the component is installed, the runtime will read this section and add the specified loggers to the component's logger MBean. Note that you do not need to add the component name prefix to the logger names; that is done automatically by the runtime. After installation completes, you can set the levels of these loggers before you start the component. This can be very useful when debugging problems in the initialization or startup processing of a component.

Note that the logger MBean does not actually create the loggers ahead of time, it merely keeps track of the logger names so that their levels can be pre-set before the component is started. Whenever a logger is requested by a component using the ComponentContext.getLogger() method, the logger's level is set to whatever level the logger MBean has saved for that logger. If the logger MBean has no level for the logger, its level is set to null to inherit its level from its parent logger.

Setting Component Logger Levels

As of the December 7, 2007 nightly build, you can use asant, asadmin, or the GlassFish admin console to list and set the component logger levels. Prior to that build, the asadmin commands were not available; only the ant commands and admin console were available.

Using ANT tasks

Here is an example using ant to list and set logger levels for the Sun HTTP binding component. First, display the loggers for the HTTP BC:

[C:/d/open3/open-esb] echo $JBI_ANT
asant -emacs -q -f C:/d/open3/open-esb/install/as8/jbi/bin/jbi_admin.xml -Djbi.username=admin -Djbi.password=adminadmin -Djbi.port=5049 -Djbi.secure=false

[C:/d/open3/open-esb] $JBI_ANT -Djbi.component.name=sun-http-binding list-component-loggers
============================================================
Component Logger for "sun-http-binding" on Target "server"
============================================================
sun-http-binding=INFO
sun-http-binding.com.sun.jbi.httpsoapbc.Extension=INFO
sun-http-binding.com.sun.jbi.httpsoapbc.HttpNormalizer=INFO
sun-http-binding.com.sun.jbi.httpsoapbc.HttpSoapBindingDeployer=INFO
sun-http-binding.com.sun.jbi.httpsoapbc.HttpSoapBindingLifeCycle=INFO
sun-http-binding.com.sun.jbi.httpsoapbc.InboundMessageProcessor=INFO
sun-http-binding.com.sun.jbi.httpsoapbc.OutboundMessageProcessor=INFO
sun-http-binding.com.sun.jbi.httpsoapbc.OutboundReceiver=INFO
sun-http-binding.com.sun.jbi.httpsoapbc.SoapDenormalizer=INFO
sun-http-binding.com.sun.jbi.httpsoapbc.SoapNormalizer=INFO
sun-http-binding.com.sun.jbi.httpsoapbc.configuration.RuntimeConfiguration=INFO
sun-http-binding.com.sun.jbi.httpsoapbc.embedded.EmbeddedServerController=INFO
sun-http-binding.com.sun.jbi.httpsoapbc.jaxwssupport.JAXWSEndpointFactory=INFO
sun-http-binding.com.sun.jbi.httpsoapbc.proxy.HttpProxy=INFO
sun-http-binding.com.sun.jbi.httpsoapbc.proxy.HttpProxySelector=INFO
sun-http-binding.com.sun.jbi.httpsoapbc.security.auth.HttpAuthenticator=INFO
sun-http-binding.com.sun.jbi.httpsoapbc.security.http.impl.BasicAuthenticator=INFO
------------------------------------------------------------

BUILD SUCCESSFUL
Total time: 0 seconds

Now, set the top-level logger's level to WARNING and display the resulting logger levels:

[C:/d/open3/open-esb] $JBI_ANT -Djbi.component.name=sun-http-binding -Djbi.logger.name=sun-http-binding -Djbi.logger.level=WARNING set-component-logger
Setting logger
  jmx connection info: (host=localhost, port=5049, secure=false, username=admin,  target=server )
Set logger succeeded. [
  INFO:(UIANT6120)Set logger level for "sun-http-binding" set on target "server"

]

BUILD SUCCESSFUL
Total time: 0 seconds
[C:/d/open3/open-esb] $JBI_ANT -Djbi.component.name=sun-http-binding list-component-loggers
============================================================
Component Logger for "sun-http-binding" on Target "server"
============================================================
sun-http-binding=WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.Extension=WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.HttpNormalizer=WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.HttpSoapBindingDeployer=WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.HttpSoapBindingLifeCycle=WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.InboundMessageProcessor=WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.OutboundMessageProcessor=WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.OutboundReceiver=WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.SoapDenormalizer=WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.SoapNormalizer=WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.configuration.RuntimeConfiguration=WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.embedded.EmbeddedServerController=WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.jaxwssupport.JAXWSEndpointFactory=WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.proxy.HttpProxy=WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.proxy.HttpProxySelector=WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.security.auth.HttpAuthenticator=WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.security.http.impl.BasicAuthenticator=WARNING
------------------------------------------------------------

BUILD SUCCESSFUL
Total time: 0 seconds

Finally, set the "Extension" logger level to FINEST and display the resulting logger levels:

[C:/d/open3/open-esb] $JBI_ANT -Djbi.component.name=sun-http-binding -Djbi.logger.name=sun-http-binding.com.sun.jbi.httpsoapbc.Extension -Djbi.logger.level=FINEST set-component-logger
Setting logger
  jmx connection info: (host=localhost, port=5049, secure=false, username=admin,  target=server )
Set logger succeeded. [
  INFO:(UIANT6120)Set logger level for "sun-http-binding" set on target "server"

]

BUILD SUCCESSFUL
Total time: 0 seconds
[C:/d/open3/open-esb] $JBI_ANT -Djbi.component.name=sun-http-binding -Djbi.logger.name=sun-http-binding.com.sun.jbi.httpsoapbc.Extension list-component-loggers
============================================================
Component Logger for "sun-http-binding" on Target "server"
============================================================
sun-http-binding.com.sun.jbi.httpsoapbc.Extension=FINEST
------------------------------------------------------------

BUILD SUCCESSFUL
Total time: 0 seconds
[C:/d/open3/open-esb] $JBI_ANT -Djbi.component.name=sun-http-binding list-component-loggers
============================================================
Component Logger for "sun-http-binding" on Target "server"
============================================================
sun-http-binding=WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.Extension=FINEST
sun-http-binding.com.sun.jbi.httpsoapbc.HttpNormalizer=WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.HttpSoapBindingDeployer=WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.HttpSoapBindingLifeCycle=WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.InboundMessageProcessor=WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.OutboundMessageProcessor=WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.OutboundReceiver=WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.SoapDenormalizer=WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.SoapNormalizer=WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.configuration.RuntimeConfiguration=WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.embedded.EmbeddedServerController=WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.jaxwssupport.JAXWSEndpointFactory=WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.proxy.HttpProxy=WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.proxy.HttpProxySelector=WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.security.auth.HttpAuthenticator=WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.security.http.impl.BasicAuthenticator=WARNING
------------------------------------------------------------

BUILD SUCCESSFUL
Total time: 0 seconds
[C:/d/open3/open-esb]

Using asadmin commands

Here's an example using the equivalent GlassFish asadmin commands in the same sequence. These commands are available starting with the nightly build from December 7, 2007. Beginning with a display of the loggers for the Sun HTTP binding component:

[C:/d/open3/open-esb] asadmin show-jbi-binding-component --port 5049 --user admin --display loggers sun-http-binding
Please enter the admin password>
sun-http-binding = INFO
sun-http-binding.com.sun.jbi.httpsoapbc.Extension = INFO
sun-http-binding.com.sun.jbi.httpsoapbc.HttpNormalizer = INFO
sun-http-binding.com.sun.jbi.httpsoapbc.HttpSoapBindingDeployer = INFO
sun-http-binding.com.sun.jbi.httpsoapbc.HttpSoapBindingLifeCycle = INFO
sun-http-binding.com.sun.jbi.httpsoapbc.InboundMessageProcessor = INFO
sun-http-binding.com.sun.jbi.httpsoapbc.OutboundMessageProcessor = INFO
sun-http-binding.com.sun.jbi.httpsoapbc.OutboundReceiver = INFO
sun-http-binding.com.sun.jbi.httpsoapbc.SoapDenormalizer = INFO
sun-http-binding.com.sun.jbi.httpsoapbc.SoapNormalizer = INFO
sun-http-binding.com.sun.jbi.httpsoapbc.configuration.RuntimeConfiguration = INFO
sun-http-binding.com.sun.jbi.httpsoapbc.embedded.EmbeddedServerController = INFO
sun-http-binding.com.sun.jbi.httpsoapbc.jaxwssupport.JAXWSEndpointFactory = INFO
sun-http-binding.com.sun.jbi.httpsoapbc.proxy.HttpProxy = INFO
sun-http-binding.com.sun.jbi.httpsoapbc.proxy.HttpProxySelector = INFO
sun-http-binding.com.sun.jbi.httpsoapbc.security.auth.HttpAuthenticator = INFO
sun-http-binding.com.sun.jbi.httpsoapbc.security.http.impl.BasicAuthenticator = INFO
Command show-jbi-binding-component executed successfully.

Now, set the top-level logger's level to WARNING and display the resulting logger levels:

[C:/d/open3/open-esb] asadmin set-jbi-component-logger --port 5049 --user admin
--component sun-http-binding "sun-http-binding=WARNING"
Please enter the admin password>
Command set-jbi-component-logger executed successfully.

[C:/d/open3/open-esb] asadmin show-jbi-binding-component --port 5049 --user admin --display loggers sun-http-binding
Please enter the admin password>
sun-http-binding = WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.Extension = WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.HttpNormalizer = WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.HttpSoapBindingDeployer = WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.HttpSoapBindingLifeCycle = WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.InboundMessageProcessor = WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.OutboundMessageProcessor = WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.OutboundReceiver = WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.SoapDenormalizer = WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.SoapNormalizer = WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.configuration.RuntimeConfiguration = WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.embedded.EmbeddedServerController = WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.jaxwssupport.JAXWSEndpointFactory = WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.proxy.HttpProxy = WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.proxy.HttpProxySelector = WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.security.auth.HttpAuthenticator = WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.security.http.impl.BasicAuthenticator = WARNING
Command show-jbi-binding-component executed successfully.

Finally, set the "Extension" logger level to FINEST and display the resulting logger levels:

[C:/d/open3/open-esb] asadmin set-jbi-component-logger --port 5049 --user admin --component sun-http-binding "sun-http-binding.com.sun.jbi.httpsoapbc.Extension=FINEST"
Please enter the admin password>
Command set-jbi-component-logger executed successfully.

 [C:/d/open3/open-esb] asadmin show-jbi-binding-component --port 5049 --user admin --display loggers sun-http-binding
Please enter the admin password>
sun-http-binding = WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.Extension = FINEST
sun-http-binding.com.sun.jbi.httpsoapbc.HttpNormalizer = WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.HttpSoapBindingDeployer = WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.HttpSoapBindingLifeCycle = WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.InboundMessageProcessor = WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.OutboundMessageProcessor = WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.OutboundReceiver = WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.SoapDenormalizer = WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.SoapNormalizer = WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.configuration.RuntimeConfiguration = WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.embedded.EmbeddedServerController = WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.jaxwssupport.JAXWSEndpointFactory = WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.proxy.HttpProxy = WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.proxy.HttpProxySelector = WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.security.auth.HttpAuthenticator = WARNING
sun-http-binding.com.sun.jbi.httpsoapbc.security.http.impl.BasicAuthenticator = WARNING
Command show-jbi-binding-component executed successfully.

Using admin console

Now here's an example using the GlassFish admin console. The screen shots are of only the frame that is relevant, not the entire browser window, just to cut down on the size. Beginning with a display of the loggers for the Sun HTTP binding component:

Now, set the top-level logger's level to WARNING:

Posted at 10:57PM Oct 25, 2007 by mwhite in Open ESB  |  Comments[1]

Hardware removal surgery

On Thursday October 11, I had the first of two hardware removal surgeries, this one to remove the tibia plate and its 14 screws. This hardware had been in my leg since April 8, 2006 (see here). I was on crutches until yesterday, and although my leg is still a bit swollen, bruised, and sore at the incision sites, today I can walk without any pain in the bone. I am thrilled to no end - prior to this, every single step I took hurt, causing me to limp. Now I can walk without any limp at all.

Here are a couple of pics of what was removed:

I had the stitches removed Wednesday, October 24, and talked to the surgeon about the fibula plate removal. I had hoped that this could be done next month. Unfortunately, the doctor wants to wait a few months before doing that, so I have to live with those stupid screws on the outside of my ankle until probably February. Being right on the ankle bone and right under the skin, they really do cause a lot of irritation, especially if I try to wear hiking boots or my motorcycle riding boots. I have to get creative with padding to make it possible to ride over long distances. Here's an X-ray of my leg with the tibia plate out. You can see all the little holes in the bone where the screws were. 

Posted at 10:43AM Oct 21, 2007 by mwhite in Motorcycle Mania  |  Comments[97]