SitemapSource calls Pipeline twice, Logging issue in Avalon

[volker . schmitt]

Hi all,

I post this also to the Avalon list, because while tracking this
SitemapSource issue I found a Avalon Logging issue also.

Ok, what happen:
Calling a Cocoon Source "cocoon://....." the Pipeline inside the Sitemap is
called twice. The reason is the following code inside the
SitemapSourceFactory

public void release( Source source ) {
    if ( null != source ) {
        if ( this.getLogger().isDebugEnabled() ) {
            this.getLogger().debug("Releasing source " + source.getURI());
        }
        ((SitemapSource)source).recycle();
    }
}

The problem is the source.getURI() inside the logging statement. Why?
Because the source is already reset after the serialization and a call to
source.getURI initialize the source again and this calles the Sitemap again
:-(

My proposal is, remove the source.getURI from the logging statement or
change the getURI() implementation to not init the Source again. I am not
sure if this URI can change after it is init?


Now to the Avalon Logging issue.
Hm I am wondering why
      if ( this.getLogger().isDebugEnabled() )
was true, because I had no log-level configured as DEBUG.
After a long time of debugging :-( I found two things.

1. org.apache.avalon.framework.logger.LogKit2AvalonLoggerAdapter
In the method:

public static org.apache.log.Logger createLogger( final Logger logger )
{
    final Hierarchy hierarchy = new Hierarchy();
    final org.apache.log.Logger logKitLogger = hierarchy.getLoggerFor( ""
);
    final LogKit2AvalonLoggerAdapter target =
        new LogKit2AvalonLoggerAdapter( logger );
    logKitLogger.setLogTargets( new LogTarget[ ] { target } );
    return logKitLogger;
}

a logKitLogger is created with "hierarchy.getLoggerFor( "" )" this defaults
the loglevel to DEBUG. The orig Logger is wrapped inside the LogTarget, so
the result loglevel of the logger is allways DEBUG independant of the orig
Logger setting.
I have add the following code after the creation of the logKitLogger

if (!logger.isDebugEnabled()) {
    if (!logger.isWarnEnabled()) {
        if (!logger.isErrorEnabled()) {
            logKitLogger.setPriority(Priority.FATAL_ERROR);
        } else {
            logKitLogger.setPriority(Priority.ERROR);
        }
    } else {
        logKitLogger.setPriority(Priority.WARN);
    }
}

and vola, now the isDebugEnabled inside the SitemapSourceFactory return
false :-)
But then I wonder why is the Logger inside the SitemapSourceFactory is a
wrapped Logger, because SitemapSourceFactory impl. LogEnabled, so the
wrapping isn't needed. After an additional debugging session I found the
reason.

2. org.apache.avalon.excalibur.component.DefaultComponentFactory
Method newInstance first checks if a Component implements "LogEnabled" and
after this it checks for "Loggable". The problem is, if a Component impl.
AbstractDualLogEnabled like ExcaliburComponentSelector the "setLogger"
method of AbstractDualLogEnabled impl. overwrites the prev. set Logger with
a wrapped LogKitLogger. Hm, I changed the order and put the check for
"LogEnabled" after the "Loggable" and :-) the Logger isn't a wrapped
LogKitLogger anymore.

Switch back to Cocoon:
There are a lot of Components inside the cocoon.xconf which has no logger
configured inside the configuration. Example are "Source Factories" and
most of the Selectors itself.

<input-modules>
<output-modules>
<source-factories>

Should we change this?


Sorry for such a long mail, but I hope this helps improve the performance
of Cocoon ;-) While debugging all this stuff I thought it's time to switch
to a new Container which hasn't all this Adapter/Wrapper classe ;-)

Volker