Bugzilla – Full Text Bug Listing
| Summary: | Indigo Java package logs lots of output | ||||||||
|---|---|---|---|---|---|---|---|---|---|
| Product: | [Technology] EPP | Reporter: | Steffen Pingel <steffen.pingel> | ||||||
| Component: | java-package | Assignee: | Igor Fedorenko <igor> | ||||||
| Status: | RESOLVED FIXED | QA Contact: | |||||||
| Severity: | major | ||||||||
| Priority: | P3 | CC: | gunnar, igor, mknauer, pascal, steffen.pingel, wayne.beaton | ||||||
| Version: | 1.4.0 | ||||||||
| Target Milestone: | 1.4.0 RC4 | ||||||||
| Hardware: | All | ||||||||
| OS: | All | ||||||||
| Whiteboard: | |||||||||
| Attachments: |
|
||||||||
|
Description
Steffen Pingel
are you running with -consolelog by any chance? (In reply to comment #1) > are you running with -consolelog by any chance? I did, but I don't know how Steffen started the Java package. Does it make a difference between looking into your .log file or starting with the -consoleLog parameter if something uses other logging frameworks? When eclipse is started with -consoleLog, m2e deliberate echoes log messages to STDOUT and we believe this is correct/expected behaviour according to http://help.eclipse.org/helios/index.jsp?topic=/org.eclipse.platform.doc.isv/reference/misc/runtime-options.html No, I didn't specify -consoleLog. Relevant discussion http://dev.eclipse.org/mhonarc/lists/cross-project-issues-dev/msg05659.html (In reply to comment #3) > When eclipse is started with -consoleLog, m2e deliberate echoes log messages to > STDOUT and we believe this is correct/expected behaviour according to > http://help.eclipse.org/helios/index.jsp?topic=/org.eclipse.platform.doc.isv/reference/misc/runtime-options.html I don't understand the relationship between -consoleLog and the amount of things that go into the log. AFAIK this parameter tells the framework to write everything to STDOUT *and* to the .log file (like a Unix tee). It doesn't change anything in the logging configuration, does it? Apart from that: How can we proceed? I'm marking this major. Igor how far have you come in finding a solution to reliably disabling log output by default in m2e? This has to get fixed for RC2. Here are my steps (on Gtk/x86_64): 1. Start Java package # tar -xzvf /stuff/dl/20110519-1055_eclipse-java-indigo-RC1-linux.gtk.x86_64.tar.gz # eclipse/eclipse -data ws 2. Open Maven Repositories view This appears on the console: 18:39:05.381 [main] DEBUG o.e.m.c.i.p.r.ProjectRegistryRefreshJob - Queued refresh request: [] 18:39:06.387 [Worker-0] DEBUG o.e.m.c.i.p.r.ProjectRegistryManager - Refreshing: [] 18:39:06.947 [Worker-0] DEBUG o.e.m.c.i.p.r.ProjectRegistryManager - Refreshed: [] 18:39:08.106 [Worker-3] INFO o.e.m.c.i.i.nexus.NexusIndexManager - Updating index for repository: central|http://repo1.maven.org/maven2 18:39:08.144 [Worker-3] DEBUG c.n.http.client.RequestBuilderBase - setUrl hasn't been invoked. Using http://localhost 18:39:08.575 [Worker-3] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider - Non cached request DefaultHttpRequest(chunked: false) GET /maven2/.index/nexus-maven-repository-index.properties HTTP/1.1 Host: repo1.maven.org Accept-Encoding: gzip Connection: keep-alive Accept: */* User-Agent: m2e/3.7.0.v20110511/0.13.0.201105171436 using Channel [id: 0x715669c7, /192.168.2.103:56140 => repo1.maven.org/207.223.240.88:80] 18:39:08.716 [New I/O client worker #1-1] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider - Request DefaultHttpRequest(chunked: false) GET /maven2/.index/nexus-maven-repository-index.properties HTTP/1.1 Host: repo1.maven.org Accept-Encoding: gzip Connection: keep-alive Accept: */* User-Agent: m2e/3.7.0.v20110511/0.13.0.201105171436 Response DefaultHttpResponse(chunked: false) HTTP/1.1 302 Moved Temporarily Server: nginx/1.0.1 Date: Sat, 21 May 2011 16:39:08 GMT Content-Type: text/html Content-Length: 160 Connection: keep-alive Location: http://mirrors.ibiblio.org/pub/mirrors/maven2/dot-index/nexus-maven-repository-index.properties 18:39:08.718 [New I/O client worker #1-1] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider - Redirecting to http://mirrors.ibiblio.org/pub/mirrors/maven2/dot-index/nexus-maven-repository-index.properties 18:39:08.850 [New I/O client worker #1-1] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider - Non cached request DefaultHttpRequest(chunked: false) GET /pub/mirrors/maven2/dot-index/nexus-maven-repository-index.properties HTTP/1.1 Host: mirrors.ibiblio.org Accept-Encoding: gzip Connection: keep-alive Accept: */* User-Agent: m2e/3.7.0.v20110511/0.13.0.201105171436 using Channel [id: 0x27da9eda] 18:39:09.114 [New I/O client worker #1-2] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider - Request DefaultHttpRequest(chunked: false) GET /pub/mirrors/maven2/dot-index/nexus-maven-repository-index.properties HTTP/1.1 Host: mirrors.ibiblio.org Accept-Encoding: gzip Connection: keep-alive Accept: */* User-Agent: m2e/3.7.0.v20110511/0.13.0.201105171436 Response DefaultHttpResponse(chunked: false) HTTP/1.1 200 OK Content-Type: application/octet-stream Accept-Ranges: bytes ETag: "1386471839" Last-Modified: Sat, 21 May 2011 08:33:39 GMT Content-Length: 1130 Date: Sat, 21 May 2011 16:39:09 GMT Server: lighttpd/1.4.26 18:39:09.118 [New I/O client worker #1-2] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider - Adding uri: http://mirrors.ibiblio.org:80 for channel [id: 0x27da9eda, /192.168.2.103:50578 => mirrors.ibiblio.org/152.19.134.44:80] 18:39:09.314 [Worker-3] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider - Non cached request DefaultHttpRequest(chunked: false) GET /maven2/.index/nexus-maven-repository-index.gz HTTP/1.1 Host: repo1.maven.org Accept-Encoding: gzip Connection: keep-alive Accept: */* User-Agent: m2e/3.7.0.v20110511/0.13.0.201105171436 using Channel [id: 0x05220c1b, /192.168.2.103:56142 => repo1.maven.org/207.223.240.88:80] 18:39:09.438 [New I/O client worker #1-3] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider - Request DefaultHttpRequest(chunked: false) ... As I already explained on epp-dev mailing list, although m2e uses slf4j logging API, it does not contribute neither slf4j provider nor configuration to Java epp package. We really have no control over what gets logged and where so cannot "fix" this from m2e end. The only short-term solution I can suggest is to exclude ch.qos.logback.slf4j bundle from Java epp package, but I am not familiar with epp packaging tooling to tell how to do it. [1] http://dev.eclipse.org/mhonarc/lists/epp-dev/msg01426.html I don't think that excluding the fragment ch.qos.logback.slf4j is a solution as I don't know all the aspects involved. (And I don't know if this would be possible at all with p2/Buckminster.) I am adding Gunnar to this bug, since I suspect that we've been hit by bug 313553 (see also bug 177851 comment 9). He should know the slf4j better since the Gyrex project is one of the main consumers. Something else that we could try is a change in the m2e bundles. By looking into the generated p2 metadata from /releases/staging I can see this here (similar requirements are there for many org.eclipse.m2e.* bundles): <unit id='org.eclipse.m2e.refactoring' version='0.13.0.201105171436'> <requires size='21'> <required namespace='osgi.bundle' name='org.slf4j.api' range='1.6.1'/> It could help to mark this requirement with optional='true'. (In reply to comment #9) > > Something else that we could try is a change in the m2e bundles. By looking > into the generated p2 metadata from /releases/staging I can see this here > (similar requirements are there for many org.eclipse.m2e.* bundles): > > <unit id='org.eclipse.m2e.refactoring' version='0.13.0.201105171436'> > <requires size='21'> > <required namespace='osgi.bundle' name='org.slf4j.api' range='1.6.1'/> > > It could help to mark this requirement with optional='true'. No, m2e has hard dependency on slf4j. m2e won't resolve or will fail with ClassNotFoundError if org.slf4j.api is not present. Please note that org.slf4j.api defines slf4j API and "NOP" (i.e. no operation) and is not a problem by itself. We can, and I think should, use import-package instead of require-bundle, but I do not believe this will change much. The SLF4J bundle in Orbit has special p2 instructions which add a requirement on *any* SLF4J logger implementation. Those were added for Helios because p2 was installing SLF4J plus JCL wrapper without a logger which made Helios fail. If M2E does not want SL4J logging by default they should likely contribute a fragment to the EPP which hooks the NOOP logger with SLF4J on startup. Of course, a logger that writes errors to the .log would likely be better. Just thinking loud.... We could remove the p2 instrucions for Indigo *if* we can ensure that SLF4J >= 1.6 is used. Starting with 1.6 SLF4J no longer fails when no logger is found (which was the issue with Helios). It still prints a message to System.err at initialization, though. (In reply to comment #12) > It still prints a message to System.err at initialization, though. The error message would be: Failed to load class "org.slf4j.impl.StaticLoggerBinder\". Defaulting to no-operation (NOP) logger implementation See " + NO_STATICLOGGERBINDER_URL + " for further details. This would get reported at every start of Eclipse which doesn't seem right to me. Can you try "M2E - slf4j over logback logging (Incubation, Optional)" feature, which can be installed from indigo rc1 repo? This is our recommended way to configure logging when m2e is explicitly installed by the user. When installed the feature configures logback using xml configuration files [1] by default, but the file gets copied to .metadata/.plugins/org.eclipse.m2e.logback.configuration and can be changed by the user to adjust logging levels, create new categories, etc, etc. We can tweak default logback.xml if necessary. If you find this log configuration acceptable for Java EPP package, we will make "M2E - slf4j over logback logging (Incubation, Optional)" feature part of our contribution towards RC2. [1] http://git.eclipse.org/c/m2e/m2e-core.git/tree/org.eclipse.m2e.logback.configuration/defaultLogbackConfiguration/logback.xml Just keep in mind that a single component in a package that is in 'incubation' leads to a change in the package name and description, since everything has to include the string 'incubation' then. -1 for including an incubating feature. Users may perceive that as a indicator for a less stable package. (In reply to comment #8) > As I already explained on epp-dev mailing list, although m2e uses slf4j logging > API, it does not contribute neither slf4j provider nor configuration to Java epp > package. We really have no control over what gets logged and where so cannot > "fix" this from m2e end. These log messages were not present before m2e was included in the package. I am afraid you will need to help provide a fix for the problem even if it's an undesired side-effect. > The only short-term solution I can suggest is to exclude ch.qos.logback.slf4j > bundle from Java epp package, but I am not familiar with epp packaging tooling > to tell how to do it. Is there some sort of system property that we could set in the config.ini or small snippet of code that we could run on startup to make slf4j use the noop logger? Entire m2e is in incubation and we plan to graduate as part of Indigo, see bug 339969. We're submitting relevant paperwork to technology pmc in the next couple of days. Yes, it is possible to configure logback with a system property and a configuration file, see http://logback.qos.ch/manual/configuration.html. (In reply to comment #16) > > (In reply to comment #8) > > As I already explained on epp-dev mailing list, although m2e uses slf4j logging > > API, it does not contribute neither slf4j provider nor configuration to Java epp > > package. We really have no control over what gets logged and where so cannot > > "fix" this from m2e end. > > These log messages were not present before m2e was included in the package. I > am afraid you will need to help provide a fix for the problem even if it's an > undesired side-effect. > To be clear, we are trying our best to provide a solution to this problem. We did offer our help to implement proper slf4j support in eclipse core level but unfortunately our offer did not receive support/interest from eclipse core committers. And as should be evident from this bug, we are now trying to come up with a solution that would satisfy Java EPP package maintainers without making changes to the core. (In reply to comment #17) > Entire m2e is in incubation and we plan to graduate as part of Indigo, see bug > 339969. We're submitting relevant paperwork to technology pmc in the next couple > of days. Igor, this is of critical importance and we may need to consider removing m2e unless this happens for Indigo. Sorry for not noticing this earlier. Pascal's comment at https://bugs.eclipse.org/bugs/show_bug.cgi?id=330226#c0 led me believe that the graduation process was proceeding and didn't hear anything to the contrary until now. > Yes, it is possible to configure logback with a system property and a > configuration file, see http://logback.qos.ch/manual/configuration.html. Markus, would that be feasible? We would need to add something like this to the vm arguments and also provide a configuration file: -Dlogback.configurationFile=/path/to/config.xml (In reply to comment #19) > (In reply to comment #17) > > Entire m2e is in incubation and we plan to graduate as part of Indigo, see bug > > 339969. We're submitting relevant paperwork to technology pmc in the next couple > > of days. > > Igor, this is of critical importance and we may need to consider removing m2e > unless this happens for Indigo. Sorry for not noticing this earlier. Pascal's > comment at https://bugs.eclipse.org/bugs/show_bug.cgi?id=330226#c0 led me > believe that the graduation process was proceeding and didn't hear anything to > the contrary until now. AFAIK, it has been the plan from the beginning to combine the release and graduation reviews together. This is a pretty common scenario. Likelihood is that m2e will graduate successfully as they have a pretty active community, mature code base, and solid understanding of EDP. (In reply to comment #19) > (In reply to comment #17) > > Entire m2e is in incubation and we plan to graduate as part of Indigo, see bug > > 339969. We're submitting relevant paperwork to technology pmc in the next couple > > of days. > > Igor, this is of critical importance and we may need to consider removing m2e > unless this happens for Indigo. Sorry for not noticing this earlier. Pascal's > comment at https://bugs.eclipse.org/bugs/show_bug.cgi?id=330226#c0 led me > believe that the graduation process was proceeding and didn't hear anything to > the contrary until now. > Steffen, is your "-1" for m2e logback configuration feature based on its incubation status or you have technical concerns/objections? I'm fine with including the feature if it fixes the logging problem. My concern is only about the incubation status. Created attachment 196488 [details]
add logback configuration file to package
It should be possible to add such a configuration file to the package without too many problems. I've attached a patch that does something in that direction:
# add a exemplary configuration file as root file
# configures and deconfigures the JVM parameters in the .ini file with a p2 touchpoint instruction
IMPORTANT 1: I don't know the exact content that should go into the configuration file, input required!
IMPORTANT 2: This is only a quick hack and requires review. Maybe there are better solutions but I think the configuration of the JVM parameters is in this case better in the p2.inf file than in the epp.product configuration. Maybe the configuration file should be moved to the configuration/ subdirectory. As I said: Review required!
I am not convinced that this is the best solution, I just wanted to demonstrate that it *should* be possible to add/remove additional configuration files via a EPP feature.
Can somebody from Java EPP package maintainers comment if m2e logback configuration feature provides sufficient and acceptable solution to the problem with excessive m2e logging on STDOUT? Created attachment 197038 [details] adding org.eclipse.m2e.logback.feature to Java package Patch applied to CVS HEAD. This patch adds the logback feature to the package (as suggested in comment #24). Not to be confused with the solution in comment #23 which could be a fallback if this one doesn't work. Now I get even more log output... Igor? $ eclipse/eclipse -data ws -consolelog org.eclipse.m2e.logback.configuration: The org.eclipse.m2e.logback.configuration bundle was activated before the state location was initialized. Will retry after the state location is initialized. org.eclipse.m2e.logback.configuration: Logback config file: /stuff/tmp/ws/.metadata/.plugins/org.eclipse.m2e.logback.configuration/logback.0.13.0.201105261543.xml org.eclipse.m2e.logback.configuration: Initializing logback org.eclipse.m2e.logback.configuration: eclipse.consoleLog=true 01:24:55,454 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy] 01:24:55,454 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml] ... And I also got a strange warning on the first start: $ eclipse/eclipse -data ws org.eclipse.m2e.logback.configuration: The org.eclipse.m2e.logback.configuration bundle was activated before the state location was initialized. Will retry after the state location is initialized. org.eclipse.m2e.logback.configuration: Logback config file: /stuff/tmp/ws/.metadata/.plugins/org.eclipse.m2e.logback.configuration/logback.0.13.0.201105261543.xml org.eclipse.m2e.logback.configuration: Initializing logback org.eclipse.m2e.logback.configuration: eclipse.consoleLog=null org.eclipse.m2e.logback.configuration: The org.eclipse.m2e.logback.configuration bundle was activated before the state location was initialized. Will retry after the state location is initialized. org.eclipse.m2e.logback.configuration: Logback config file: /stuff/tmp/ws/.metadata/.plugins/org.eclipse.m2e.logback.configuration/logback.0.13.0.201105261543.xml org.eclipse.m2e.logback.configuration: Initializing logback org.eclipse.m2e.logback.configuration: eclipse.consoleLog=null There is a relatively small window of time during Eclipse startup during which m2e logback configuration bundle waits for workspace location information to become available. This is necessary in order to read logback configuration file from workspace .metadata/... directory. The messages that you see come from this logic and only very few messages are expected to appear in STDOUT under normal conditions. Once logback is configured, logging will be performed according to xml configuration file [1]. This is at least the expected behaviour and this is how it works when I install m2e logback configuration manually (just checked rc2 on osx). Do you think described behaviour is acceptable? Do not see more messages coming from m2e and m2e logback configuration? If yes, is there test package I can use to troubleshoot extra messages? or instructions how to build the package locally. [1] http://git.eclipse.org/c/m2e/m2e-core.git/tree/org.eclipse.m2e.logback.configuration/defaultLogbackConfiguration/logback.xml I tried 20110531-2005 java epp package on osx and only see 4 STDOUT messages early in eclipse startup. These are expected. (In reply to comment #29) > I tried 20110531-2005 java epp package on osx and only see 4 STDOUT messages > early in eclipse startup. These are expected. I would not expect any output on the console unless -consolelog is specified. Igor, can you suppress these messages by default? Another unrelated problem I noticed is that the org.eclipse.m2e.logback.appender bundle specifies Bundle-Vendor/Bundle-Name in the manifest instead of proper identifiers. If I specify -consolelog a lot additional output is logged that I do not get when I don't specify that option. My understanding of http://help.eclipse.org/helios/index.jsp?topic=/org.eclipse.platform.doc.isv/reference/misc/runtime-options.html is that -consolelog should simply copy log output to the console but not actually change the volume of messages. Igor, can you change the behavior so additional log output is only generated when -debug (or some other option is specified)? In summary, I would prefer if the Java package had same logging behavior as the Eclipse SDK and all other EPP packages. I believe I addressed all these concerns, please try new m2e 1.0.0.201106052308 available from http://download.eclipse.org/technology/m2e/milestones/1.0 See (In reply to comment #30) > (In reply to comment #29) > > I tried 20110531-2005 java epp package on osx and only see 4 STDOUT messages > > early in eclipse startup. These are expected. > > I would not expect any output on the console unless -consolelog is specified. > Igor, can you suppress these messages by default? > Done. > Another unrelated problem I noticed is that the > org.eclipse.m2e.logback.appender bundle specifies Bundle-Vendor/Bundle-Name in > the manifest instead of proper identifiers. Fixed. > > If I specify -consolelog a lot additional output is logged that I do not get > when I don't specify that option. My understanding of > http://help.eclipse.org/helios/index.jsp?topic=/org.eclipse.platform.doc.isv/reference/misc/runtime-options.html > is that -consolelog should simply copy log output to the console but not > actually change the volume of messages. Igor, can you change the behavior so > additional log output is only generated when -debug (or some other option is > specified)? This is how m2e logging is configured by default, i.e. -consolelog makes messages appear in STDOUT but -consolelog does not change log level. Note that m2e logs to .metadata/.plugins/org.eclipse.m2e.logback.configuration/0.log by default. I did reduce log severity of some messages from INFO to more appropriate DEBUG level, so there should be less logging by default now. m2e will still print INFO and more critical log messages to console when -consolelog is specified and I believe this is correct and expected behaviour. > > In summary, I would prefer if the Java package had same logging behavior as the > Eclipse SDK and all other EPP packages. The only long-term solution is to introduce slf4j support at Eclipse platform level. Otherwise, individual components are bound to ship with inconsistent and conflicting logging configuration. Thanks a lot for making these changes! The logging works as expected with the 1.0.0.201106052308 build. |