Bugzilla – Full Text Bug Listing
| Summary: | document how to set up the Virgo kernel with Janino to allow for greater logback capabilities | ||||||
|---|---|---|---|---|---|---|---|
| Product: | [RT] Virgo | Reporter: | Eric Hough <k2eric> | ||||
| Component: | runtime | Assignee: | Glyn Normington <glyn.normington> | ||||
| Status: | CLOSED FIXED | QA Contact: | |||||
| Severity: | enhancement | ||||||
| Priority: | P3 | CC: | b.kapukaranov, glyn.normington, hsiliev, k2eric | ||||
| Version: | unspecified | Flags: | glyn.normington:
documentation+
|
||||
| Target Milestone: | 3.5.0.M02 | ||||||
| Hardware: | PC | ||||||
| OS: | Linux | ||||||
| Whiteboard: | |||||||
| Bug Depends on: | 362095 | ||||||
| Bug Blocks: | |||||||
| Attachments: |
|
||||||
|
Description
Eric Hough
Janino [1] is only required to use Java boolean expressions in logback filters [2]. For example, Groovy boolean expressions can be used without Janino (but with Groovy support instead). Janino seems to comprise two JARs: janino.jar and commons-compiler.jar. Both these are from codehaus and are covered by a new BSD license. Both JARs are covered by the approved CQ 4447 which Virgo could piggy-back on. The Logback documentation [3] says that only janino.jar is required, whereas the Janino documentation implies that janino.jar depends on commons-compiler.jar, so it is possible that both JARs are required. So we have two ways of making Janino filters easier to use in Virgo. We could include the Janino JAR(s) in lib, modify the launch properties, and add (mandatory) package imports to Medic core. This would slow down Virgo startup unnecessarily for any users not wanting to use Janino, but would make Janino - at a specific version - available "out of the box". The slow down may be minimal given the small size of Janino, although I have not yet measured it. Alternatively we could add optional package imports to Medic core leaving it to users who want to use Janino to put the JAR(s) - at the version of their choosing - in lib and modify the launch properties. This avoids any overhead for users not wanting Janino but complicates the setup process for users who do (and probably therefore complicate the Virgo documentation and increase the number of queries raise by users, especially those who fail to read the documentation). [1] http://docs.codehaus.org/display/JANINO/Home [2] http://logback.qos.ch/manual/filters.html [3] http://logback.qos.ch/setup.html The first approach is to be preferred as the overhead of Janino is likely to be very small. It seems that commons-compiler.jar *is* required. I have raised CQ 4739 to cover Virgo's use of janino.jar and commons-compiler.jar. (In reply to comment #2) > It seems that commons-compiler.jar *is* required. FWIW I haven't loaded commons-compiler.jar and haven't had any issues. Of course, I may not be exercising a feature that requires it. But my hunch is that Logback doesn't use any aspect of Janino that requires commons-compiler.jar. As you noted, there's no mention of commons-compiler.jar in the Logback setup docs. I've posted this question on Logback's user list [1] and will report back with any responses. [1] http://www.qos.ch/pipermail/logback-user/2011-January/002001.html Thanks. Logback's documentation is superb, so thanks for checking as it would be nice to avoid unnecessary dependencies. Got a nice response from the logback mailing list [1]: > commons-compiler is needed for Janino 2.6 and later. Logback was tested with Janino 2.4.x and 2.5.x. This probably explains why I'm not having any problems as I'm using Janino version 2.5.15 from Spring's EBR [2]. [1] http://www.qos.ch/pipermail/logback-user/2011-January/002002.html [2] https://ebr.springsource.com/repository/app/bundle/version/detail?name=com.springsource.org.codehaus.janino&version=2.5.15 Thanks Eric. CQ 4739 is approved, so we are free to implement this enhancement. Note to eventual implementer: you need to decide whether to package the janino JARs inside medic core (on the bundle classpath) or turn these JARs into bundles and import the relevant packages with suitable version ranges. The latter is probably preferable as it is more future proof: users could upgrade janino without having to rebuild medic core. Since medic can function without janino, it would probably be worth making medic core use optional imports of janino. This would also give users with extreme performance requirements the option of deleting janino to avoid loading it during startup. Please refer to the logback documentation to determine the appropriate start of the import version range. To make the janino JARs available as bundles to the build, it is currently necessary to add them to the EBR as we don't yet have support for building directly from Orbit. There was some discussion recently about possibly moving Logback out of the medic core bundle and importing its packages instead. I'm following up that direction as it would simplify the implementation of this enhancement. Once this feature is implemented, we should experiment with the use of Janino in Virgo to improve performance. Currently, the SIFTED_LOG_FILE appender defined in the kernel's serviceability.xml sets a default applicationName of virgo-kernel and so log entries which are not associated with a specific application get logged in virgo-kernel/log.log. However, this is a waste since those log entries are already logged in logs/log.log.
Using Janino as described in [1] might speed things up by avoiding unnecessary file I/O in that common case. I think the gist would be to change servicability.xml to include a filter:
<appender name="SIFTED_LOG_FILE" class="ch.qos.logback.classic.sift.SiftingAppender">
<discriminator>
<Key>applicationName</Key>
<DefaultValue>virgo-kernel</DefaultValue>
</discriminator>
<sift>
<appender name="${applicationName}_LOG_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<filter class="ch.qos.logback.core.filter.EvaluatorFilter">
<!-- JaninoEventEvaluator requires Janino -->
<evaluator class="ch.qos.logback.classic.boolex.JaninoEventEvaluator">
<expression>
mdc == null || mdg.get("isolatedLogName") == null
</expression>
</evaluator>
<OnMismatch>NEUTRAL</OnMismatch>
<OnMatch>DENY</OnMatch>
</filter>
<file>serviceability/logs/${applicationName}/log.log</file>
etc.
</appender>
</sift>
</appender>
Note that this would cause problems if someone naively deleted Janino to try to speed Virgo up - they would also have to delete the above filter. OTOH if Virgo was slower without Janino, there would not be a good reason to delete it.
[1] http://www.mail-archive.com/logback-user@qos.ch/msg01926.html
Whoops! The expression should of course be:
<expression>
mdc == null || mdg.get("applicationName") == null
</expression>
Or, better still:
<expression>
mdc == null || mdc.get("applicationName") == null
</expression>
Janino 2.6.1 including commons compiler published to SpringSource Enterprise Bundle Repository and committed as a351ad1f4d04ec3e10961e6a3bdb3d9f7fa5225c. Ivy coordinates: org="org.codehaus.janino" name="com.springsource.org.codehaus.commons.compiler" rev="2.6.1" org="org.codehaus.janino" name="com.springsource.org.codehaus.janino" rev="2.6.1" I experimented with adding Janino into the Virgo kernel and it seems like Janino's class loading behaviour may be a show-stopper. I configured serviceability.xml as in the earlier comments and it made no noticeable difference to what was logged. The debugger showed a class loading issue on the class org.slf4j.Marker: org.codehaus.janino.JaninoRuntimeException: Trying to add an auxiliary class "org.slf4j.Marker" while another class with the same name is already loaded at org.codehaus.janino.SimpleCompiler$AuxiliaryClassLoader.addAuxiliaryClass(SimpleCompiler.java:266) at org.codehaus.janino.SimpleCompiler$AuxiliaryClassLoader.access$200(SimpleCompiler.java:245) at org.codehaus.janino.SimpleCompiler.classToType(SimpleCompiler.java:346) at org.codehaus.janino.ScriptEvaluator.makeMethodDeclaration(ScriptEvaluator.java:691) at org.codehaus.janino.ScriptEvaluator.cook(ScriptEvaluator.java:480) at org.codehaus.janino.ScriptEvaluator.cook(ScriptEvaluator.java:345) at org.codehaus.janino.SimpleCompiler.cook(SimpleCompiler.java:194) at org.codehaus.commons.compiler.Cookable.cook(Cookable.java:80) at org.codehaus.commons.compiler.Cookable.cook(Cookable.java:72) at org.codehaus.janino.ScriptEvaluator.<init>(ScriptEvaluator.java:134) at ch.qos.logback.core.boolex.JaninoEventEvaluatorBase.start(JaninoEventEvaluatorBase.java:58) at ch.qos.logback.core.joran.action.NestedComplexPropertyIA.end(NestedComplexPropertyIA.java:167) at ch.qos.logback.core.joran.spi.Interpreter.callEndAction(Interpreter.java:315) at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:194) at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:180) at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:52) at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:134) at ch.qos.logback.core.sift.AppenderFactoryBase.buildAppender(AppenderFactoryBase.java:43) at ch.qos.logback.core.sift.SiftingAppenderBase.append(SiftingAppenderBase.java:80) at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:85) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:64) at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:285) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:272) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:473) at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:427) at ch.qos.logback.classic.Logger.info(Logger.java:631) at org.eclipse.virgo.medic.log.osgi.OSGiLogServiceListener.log(OSGiLogServiceListener.java:66) at org.eclipse.virgo.medic.log.osgi.OSGiLogServiceListener.logged(OSGiLogServiceListener.java:43) at org.eclipse.equinox.log.internal.ExtendedLogReaderServiceFactory.safeLogged(ExtendedLogReaderServiceFactory.java:86) at org.eclipse.equinox.log.internal.ExtendedLogReaderServiceFactory$LogTask.run(ExtendedLogReaderServiceFactory.java:35) at org.eclipse.equinox.log.internal.SerializedTaskQueue$1.run(SerializedTaskQueue.java:33) It appears the this class is loadable from the application class loader and somehow Janino is conflicted about where the class should come from. I have seen a couple of calls to Thread.getContextClassLoader in JaninoEventEvaluator.start and in a field declaration of SimpleCompiler, but I haven't seen any way of configuring Janino to avoid using the thread context class loader. If anyone want to play with this over the Christmas holidays, I've put a temporary zip here: http://dl.dropbox.com/u/2487064/virgo-kernel-3.1.0.BUILD-20111223144240.zip I finally got Janino working and ran a test along the lines of comment 10. My hope was that, by preventing 300 KB of logging output going to serviceability/logs/virgo-kernel/log.log, kernel startup might be faster. In fact startup time went from 3 seconds to 5.3 seconds, so it seems that using Janino with logback is pretty expensive. Eric: I'd be interested in hearing whether this matters to you. Perhaps you had in mind some sophisticated logging scenario, perhaps restricted to a test environment. Unless there is a strong case in favour of bundling Janino with the kernel, I'm inclined not to implement this enhancement. Now that bug 362095 has been implemented, it's reasonably straightforward for anyone to bolt Janino into the kernel on their own. Here's a summary of the changes that were necessary in the above example: 1. Place the Janino and commons compiler JARs, both at v2.6.1 (available from the SpringSource Enterprise Bundle Repository) into lib/kernel. 2. Create a fragment of the Janino JAR with a manifest as follows and place the fragment in lib/kernel/janinofragment.jar: Manifest-Version: 1.0 Bundle-ManifestVersion: 2 Bundle-SymbolicName: janinofragment Bundle-Name: Janino Fragment Fragment-Host: com.springsource.org.codehaus.janino;bundle-version="[2.6.1, 3)" Import-Package: org.slf4j;version="[1.6.1, 2)", ch.qos.logback.classic;version="[0.9.28, 1)", ch.qos.logback.classic.spi;version="[0.9.28, 1)" This should cover the packages that need to be wired from the Janino bundle given that Logback 0.9.28 (and even v1.0.0) does not allow us to use another bundle class loader as Janino's "parent" class loader - see [1]. 3. Add the following lines to the launcher.bundles property in lib/org.eclipse.virgo.kernel.launcher.propertes: file:lib/kernel/com.springsource.org.codehaus.janino-2.6.1.jar,\ file:lib/kernel/com.springsource.org.codehaus.commons.compiler-2.6.1.jar,\ file:lib/kernel/janinofragment.jar,\ 4. Add the following as the first child of the <appender> element for RollingFileAppender in config/serviceability.xml: <filter class="ch.qos.logback.core.filter.EvaluatorFilter"> <evaluator class="ch.qos.logback.classic.boolex.JaninoEventEvaluator"> <expression> (mdc == null) || (mdc.get("applicationName") == null) </expression> </evaluator> <OnMismatch>NEUTRAL</OnMismatch> <OnMatch>DENY</OnMatch> </filter> [1] http://mailman.qos.ch/pipermail/logback-user/2012-January/002916.html I raised LBCORE-244 ([1]) to ensure logback correctly sets Janino's "parent" class loader. I coded a fix and tested this with Virgo and the steps in comment 15 then reduce to: 1. Place the Janino and commons compiler JARs, both at v2.6.1 (available from the SpringSource Enterprise Bundle Repository) into lib/kernel. 2. Add the following lines to the launcher.bundles property in lib/org.eclipse.virgo.kernel.launcher.propertes: file:lib/kernel/com.springsource.org.codehaus.janino-2.6.1.jar,\ file:lib/kernel/com.springsource.org.codehaus.commons.compiler-2.6.1.jar,\ 3. Add the following as the first child of the <appender> element for RollingFileAppender in config/serviceability.xml: <filter class="ch.qos.logback.core.filter.EvaluatorFilter"> <evaluator class="ch.qos.logback.classic.boolex.JaninoEventEvaluator"> <expression> (mdc == null) || (mdc.get("applicationName") == null) </expression> </evaluator> <OnMismatch>NEUTRAL</OnMismatch> <OnMatch>DENY</OnMatch> </filter> On the basis that this is straightforward, and that, even before LBCORE-244 is fixed, there is a relatively straightforward solution as per comment 15, I am closing this bug. [1] http://jira.qos.ch/browse/LBCORE-244 (In reply to comment #15) > In fact startup time went from 3 seconds to 5.3 seconds, so it seems that using > Janino with logback is pretty expensive. > > Eric: I'd be interested in hearing whether this matters to you. Perhaps you had > in mind some sophisticated logging scenario, perhaps restricted to a test > environment. Sorry it took me so long to respond to you! It's certainly disappointing that simply adding Janino incurs such a performance hit. My use of Janino is just limited to filtering out log noise (via ch.qos.logback.core.filter.EvaluatorFilter) - nothing more sophisticated than that. We already have a Ant script that customizes a "raw" Virgo distribution to suit our needs, so bolting on Janino as per your instructions is not a deal breaker for me. The only followup question I have is; Would it be worth it to include your instructions in comment 15 to the Virgo User Guide Appendix? Thanks for your continued work on this. Cheers. (In reply to comment #17) > (In reply to comment #15) > > In fact startup time went from 3 seconds to 5.3 seconds, so it seems that using > > Janino with logback is pretty expensive. > > > > Eric: I'd be interested in hearing whether this matters to you. Perhaps you had > > in mind some sophisticated logging scenario, perhaps restricted to a test > > environment. > > Sorry it took me so long to respond to you! It's certainly disappointing that > simply adding Janino incurs such a performance hit. My use of Janino is just > limited to filtering out log noise (via > ch.qos.logback.core.filter.EvaluatorFilter) - nothing more sophisticated than > that. We already have a Ant script that customizes a "raw" Virgo distribution > to suit our needs, so bolting on Janino as per your instructions is not a deal > breaker for me. > > The only followup question I have is; Would it be worth it to include your > instructions in comment 15 to the Virgo User Guide Appendix? Yes, good idea. I've re-opened this bug to cover that. > > Thanks for your continued work on this. Cheers. You're welcome. Fixed in documentation commit b3914ad6fb4aabbe6fbc30b6a757440af975d771 on branch 364571-introduce-nano. The new section is attached to this bug, but please note that it is framed in terms of the recently modified directory structure that will appear in 3.5.0.M02. Created attachment 209456 [details]
New Janino section for User Guide
|