Bugzilla – Full Text Bug Listing
| Summary: | [medic] included logback.xml is not picked up from root of the bundle | ||||||||
|---|---|---|---|---|---|---|---|---|---|
| Product: | [RT] Virgo | Reporter: | Dmitry Sklyut <dmitry> | ||||||
| Component: | unknown | Assignee: | Glyn Normington <glyn.normington> | ||||||
| Status: | CLOSED FIXED | QA Contact: | |||||||
| Severity: | normal | ||||||||
| Priority: | P3 | CC: | glyn.normington | ||||||
| Version: | 2.1.0.M03-incubation | ||||||||
| Target Milestone: | 2.1.0.RC1-incubation | ||||||||
| Hardware: | Macintosh | ||||||||
| OS: | Mac OS X - Carbon (unsup.) | ||||||||
| URL: | http://dev.eclipse.org/mhonarc/lists/virgo-dev/msg00272.html | ||||||||
| Whiteboard: | |||||||||
| Attachments: |
|
||||||||
|
Description
Dmitry Sklyut
Created attachment 179751 [details]
Eclipse project to generate a bundle
Created attachment 179752 [details]
Test bundle
The attached test bundle uses three logger configuration: 1. Public - i.e. configured from /config/serviceability.xml <logger level="INFO" additivity="false" name="com.dsklyut.virgo"> <appender-ref ref="EVENT_LOG_STDOUT" /> <appender-ref ref="SIFTED_LOG_FILE" /> </logger> 2. Private Instance Logger - i.e. instance field in the class. Configured in logback.xml in root of the bundle (PrivateLoggerInstanceFILE) 3. Logger that is looked up on each invocation - Configured in logback.xml in root of the bundle. (PrivateLookupLoggerFILE) The bundle uses Spring scheduler to call into a method every 10 seconds. Currently only see logs from #1, i.e. Public logger. Can this be patched by adding equinox implementation packages to the list of boot delegation packages for inner framework? (In reply to comment #4) > Can this be patched by adding equinox implementation packages to the list of > boot delegation packages for inner framework? I suspect not as it's part of the design of that implementation of nested frameworks to use a separate class loader. For example, it may be that the identity of the nested framework is rooted in class statics. After I've found some time to dig into this a little more and if I can't see a solution in Virgo, I'll probably see what the Equinox guys make of it and they can advise definitively on whether such a patch would be viable. I dug into this a little. I think the problem is that medic is using the package admin service from the kernel region to inquire about a bundle in the user region and, as you observe, package admin has a dependency on Equinox internals. So I am optimistic that FrameworkUtil.getBundle could solve the problem. However, before I try that, I want to reproduce your exact issue. I dropped the test bundle into pickup of a running kernel and saw entries like this in log.log: [2010-10-01 12:26:56.901] simple-log-test-scheduler-1 com.dsklyut.virgo.medic.test.internal.LogClient PublicLogger 'Called into log for the 4 time' [2010-10-01 12:26:56.901] simple-log-test-scheduler-1 PrivateLoggerInstance PrivateLoggerInstance 'Called into log for the 4 time' [2010-10-01 12:26:56.901] simple-log-test-scheduler-1 PrivateLookupLogger PrivateLookupLogger 'Called into log for the 4 time' This seems to be working perfectly. I was running with a recent kernel which uses Equinox 3.6.1, so I wonder if Equinox has fixed this problem? (In reply to comment #6) Output looks like I would expect it. Would there be any difference between a kernel and web-server setup? It does not sound likely but... I will test with a master build later today. Thanks! (In reply to comment #7) > (In reply to comment #6) > Output looks like I would expect it. Would there be any difference between a > kernel and web-server setup? It does not sound likely but... There is no significant difference as far as your test is concerned. > > I will test with a master build later today. Thanks! That would be helpful. We'd like to know if this needs fixing before we release. I just realized that I forgot one very important piece of information. ROOT logger in config/serviceablility.xml must be set to WARN or something above INFO. Testing now with M4, 2.1 branch and master I just re-tested with config/serviceability.xml ROOT level set to WARN. I tested m4, m3, master and 2.1.x local builds. Still see the same issue. Yes, the problem reproduces when the ROOT level is sssset to WARN. The first step towards a fix was to change medic to use FrameworkUtil.getBundle. This successfully returned the test bundle. However, it also caused a path to be exercised which clearly hadn't been exercised before. A class loading hook in the Virgo web layer is advised by the entry/exit tracing aspect (in medic) and this caused an unbounded recursion. The next step was to narrow the aspect slightly to exclude the package containing the web class loading hook. A logger instance is now built successfully by the test bundle. I then started debugging the path when the Logger.info calls are made. The public logger doesn't do anything as it doesn't appear to have any appenders (Logger.aai is null). Perhaps this is some kind of configuration error as there is no bundle-specific configuration for the public logger and so I guess it delegates to the parent and the logging gets filtered out. The private logger instance gets further. I can see it writing to an output stream, thus: ResilientFileOutputStream(ResilientOutputStreamBase).write(byte[], int, int) line: 53 ResilientFileOutputStream(OutputStream).write(byte[]) line: 58 PatternLayoutEncoder(LayoutWrappingEncoder<E>).doEncode(E) line: 103 FileAppender<E>(OutputStreamAppender<E>).writeOut(E) line: 193 FileAppender<E>.writeOut(E) line: 220 FileAppender<E>(OutputStreamAppender<E>).subAppend(E) line: 216 FileAppender<E>(OutputStreamAppender<E>).append(E) line: 108 FileAppender<E>(UnsynchronizedAppenderBase<E>).doAppend(E) line: 91 SiftingAppender(SiftingAppenderBase<E>).append(E) line: 94 SiftingAppender(AppenderBase<E>).doAppend(E) line: 85 AppenderAttachableImpl<E>.appendLoopOnAppenders(E) line: 64 Logger.appendLoopOnAppenders(ILoggingEvent) line: 283 Logger.callAppenders(ILoggingEvent) line: 270 Logger.buildLoggingEventAndAppend(String, Marker, Level, String, Object[], Throwable) line: 471 Logger.filterAndLog_1(String, Marker, Level, String, Object, Throwable) line: 443 Logger.info(String, Object) line: 633 LogClient.logPrivateInstance(String) line: 40 LogClient.logAll() line: 28 ... The file being written to has a path of "serviceability/PrivateLoggerInstance/3.log" (I'm on the 3rd scheduling of the test bundle, which may account for the 3.log). However, I can't find any evidence of this file on disk. Perhaps there is a problem creating the PrivateLoggerInstance directory, but the strange thing is that the write to the file seems to succeed, which makes me think the data must be going somewhere. The privateLookupLogger gets a logger assigned to it ok. The logging behaviour is then similar to the private logger instance and the log entry is successfully written to the file "serviceability/PrivateLookupLogger/3.log" and disappears without trace. The file does indeed increment to .../4.log for the next log call. This matches the specification of the discriminator in the bundle's logback.xml:
<appender name="PrivateLoggerInstanceFILE" class="ch.qos.logback.classic.sift.SiftingAppender">
<discriminator>
<Key>jobid</Key>
<DefaultValue>unknown</DefaultValue>
</discriminator>
<sift>
<appender name="FILE-${jobid}" class="ch.qos.logback.core.FileAppender">
<File>serviceability/PrivateLoggerInstance/${jobid}.log
</File>
<Append>false</Append>
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<Pattern>%d %level - %msg%n</Pattern>
</encoder>
</appender>
</sift>
</appender>
This seems a bit odd to me. Why sift into numerous separate log files?
I am not particularly confident that the test bundle is correctly configured, so I will attempt to ripple the medic changes up so that you can experiment with the configuration. (In reply to comment #11) > The public logger doesn't do anything as it doesn't appear to have any > appenders (Logger.aai is null). Perhaps this is some kind of configuration > error as there is no bundle-specific configuration for the public logger and so > I guess it delegates to the parent and the logging gets filtered out. In my set-up I created (from comment #3) 1. Public - i.e. configured from /config/serviceability.xml <logger level="INFO" additivity="false" name="com.dsklyut.virgo"> <appender-ref ref="EVENT_LOG_STDOUT" /> <appender-ref ref="SIFTED_LOG_FILE" /> </logger> > The private logger instance gets further. I can see it writing to an output > The file being written to has a path of > "serviceability/PrivateLoggerInstance/3.log" (I'm on the 3rd scheduling of the > test bundle, which may account for the 3.log). However, I can't find any > evidence of this file on disk. Perhaps there is a problem creating the > PrivateLoggerInstance directory, but the strange thing is that the write to the > file seems to succeed, which makes me think the data must be going somewhere. This was actually secondary test. I wanted to know if log location needed to be absolute or relative to the root of the server. Entries in config/serviceability.xml are treated as relative to the root of virgo. (In reply to comment #12) > This seems a bit odd to me. Why sift into numerous separate log files? Just a test. We have a requirement here to write out a separate log per spring-batch execution and we use job execution id and MDC to specify file name. Sorry for missing the serviceability.xml change. Anyway, I am now seeing the subdirectories PrivateLoggerInstance PrivateLookupLogger in the serviceability directory with the expected contents. However, the public logger still does not get any appenders. The ripple has reached web (third time lucky - the first time I forgot to commit medic :-( and the second time hit a network glitch and failed to download dependencies) so you may be able to try it out before long. The ripple is done, so if you git fetch the web server repo and check out the 2.1.x branch and do a build, you should be able to do the necessary experimentation to confirm whether this bug is now fixed or whether we are still missing a trick. Good luck! (In reply to comment #17) > The ripple is done, so if you git fetch the web server repo and check out the > 2.1.x branch and do a build, you should be able to do the necessary > experimentation to confirm whether this bug is now fixed or whether we are > still missing a trick. Good luck! Confirmed fixed! |