Bugzilla – Full Text Bug Listing
| Summary: | Logger Exception when starting ECP | ||||||||
|---|---|---|---|---|---|---|---|---|---|
| Product: | [Eclipse Project] Platform | Reporter: | Franziska Haunolder <franziska.haunolder> | ||||||
| Component: | Runtime | Assignee: | platform-runtime-inbox <platform-runtime-inbox> | ||||||
| Status: | RESOLVED FIXED | QA Contact: | |||||||
| Severity: | normal | ||||||||
| Priority: | P3 | CC: | 377399, Alfredo.Bencomo, daniel_megert, dj.houghton, mbertran, pwebster, remy.suen, stephan202, thatnitind, thematto, tjwatson | ||||||
| Version: | 3.7 | ||||||||
| Target Milestone: | 3.8 M5 | ||||||||
| Hardware: | All | ||||||||
| OS: | All | ||||||||
| Whiteboard: | |||||||||
| Attachments: |
|
||||||||
|
Description
Franziska Haunolder
These folks are experiencing this issue too. http://www.eclipse.org/forums/index.php/m/699372/ This is happening to all developers that use eclipse at my work... Hi, I'm getting the same error. I use a wrapper to ease all logging process. In my plugin's wrapper class (inheriting org.eclipse.ui.plugin.AbstractUIPlugin) i got the error when executing super.getLog().log(new Status(IStatus.INFO, getId(), msg)); The last entry from the forums was interesting: Bundle bundle = Platform.getBundle(Platform.PI_RUNTIME); Evidently the value of this constant isn't "org.eclipse" in Indigo. I'm at a bit of a loss as to where I should triage this defect; I doesn't appear to be a platform issue (I've never had this issue using base eclipse). Does anybody here know if there's a common root cause (where I could route this for a common fix) or is it just that many bundles have fallen into the same issue of using the string rather than the constant ? Eric, The only other off-site features we use are subclipse, multiclipboard and pydev. Could one of these be the cause? Perhaps one of them is common to all? Matt, I observe this issue as well. Of the three extensions mentioned I'm only using Subclipse. Hope that helps. Regards, Stephan I suspect that Subclipse is likely the suspect given the comments on this bug and the forum thread. I am not sure about comment 0 though. Franziska, do you always get the NPE on startup? What is ECP? For me problim was solved by replacing all tigris subvershion files from plugins I'm not using subversion and I still get the same error. I think it has more to do with the logging system changes than any other thing. Actually, this bug is generic for all plugins that use the logging system. I seems the way to access the log has changed and the old way is no longer available? It should have been kept while markiing it as deprecated, souldnt't it? (In reply to comment #9) > I think it has more to do with the logging system changes than any other thing. > Actually, this bug is generic for all plugins that use the logging system. I > seems the way to access the log has changed and the old way is no longer > available? I think whatever way people used to be calling was wrong and never supported and only worked by luck. In any case, the isLoggable(*) method was added by bug 292135. Equinox Framework, please advise. (In reply to comment #10) > (In reply to comment #9) > > I think it has more to do with the logging system changes than any other thing. > > Actually, this bug is generic for all plugins that use the logging system. I > > seems the way to access the log has changed and the old way is no longer > > available? > > I think whatever way people used to be calling was wrong and never supported > and only worked by luck. > > In any case, the isLoggable(*) method was added by bug 292135. > > Equinox Framework, please advise. From page http://wiki.eclipse.org/FAQ_How_do_I_use_the_platform_logging_facility%3F which is 1st result for google search "eclipse logging", I get a page that explains how to use the logging system. In that page, it's suggested to use method Plugin.getLog() to access the error log. An example of logging methods is given as well, which look exactly the same as the ones I have on my plugins. This is what is generating this NullPointerException in the new version. (In reply to comment #11) > From page > http://wiki.eclipse.org/FAQ_How_do_I_use_the_platform_logging_facility%3F which > is 1st result for google search "eclipse logging", I get a page that explains > how to use the logging system. > In that page, it's suggested to use method Plugin.getLog() to access the > error log. An example of logging methods is given as well, which look exactly > the same as the ones I have on my plugins. This is what is generating this > NullPointerException in the new version. Yes, I realize that. However, I see that same code path in many places and I've not seen this NPE before. The bug is solved. The problem was trying to log before plugin's start() method execution. It wos working before indigo version, but seems not to be working any more. I reached this conclusion throught the following steps: The error does happen when AncoraAbstractPlugin.java:57 is executed. This line contains the following code: getLog().log(new Status(IStatus.INFO, getId(), msg)); The class is subclass of AbstractUIPlugin and parameters have following values: IStatus.INFO == 1 getId() == "AncoraPipePlugin" msg == "Plugin started: AncoraPipePlugin" Stack trace is: java.lang.NullPointerException at org.eclipse.core.internal.runtime.Log.isLoggable(Log.java:101) at org.eclipse.equinox.log.internal.ExtendedLogReaderServiceFactory.safeIsLoggable(ExtendedLogReaderServiceFactory.java:59) at org.eclipse.equinox.log.internal.ExtendedLogReaderServiceFactory.logPrivileged(ExtendedLogReaderServiceFactory.java:164) at org.eclipse.equinox.log.internal.ExtendedLogReaderServiceFactory.log(ExtendedLogReaderServiceFactory.java:150) at org.eclipse.equinox.log.internal.ExtendedLogServiceFactory.log(ExtendedLogServiceFactory.java:65) at org.eclipse.equinox.log.internal.ExtendedLogServiceImpl.log(ExtendedLogServiceImpl.java:87) at org.eclipse.equinox.log.internal.LoggerImpl.log(LoggerImpl.java:54) at org.eclipse.core.internal.runtime.Log.log(Log.java:60) at org.ub.pluginutils.AncoraAbstractPlugin.log(AncoraAbstractPlugin.java:57) ... With a little of debugging, I got that at Log.java:101, variables have the following values: PlatformLogWriter.EQUINOX_LOGGER_NAME == "org.eclipse.equinox.logger" loggerName == "org.eclipse.equinox.logger" bundle == null /**** this is generating the exception!! ***/ loggingBundle.getBundleId() == 10817 logLevel == 3 loggingBundle is instance of BundleHost As I see, the problem is the field bundle, which is null. This seems to come from a bad initialization (when Log.bundle is set). Is this possible? Log initialization in Plugin class might be done at Plugin.java:291, where InternalPlatform.getDefault().getLog(bundle) is called. It seems that this is called with bundle==null for that plugin, being bundle a field of class Plugin, which is initialized at deprecated public Plugin(IPluginDescriptor descriptor) (not used by me) or at start. Now I realize the problem!!: I called log at my overrided start method before calling super.start(), so bundle is not yet initialized. Manu The bug is solved. The problem was trying to log before plugin's start() method execution. It wos working before indigo version, but seems not to be working any more. I reached this conclusion throught the following steps: The error does happen when AncoraAbstractPlugin.java:57 is executed. This line contains the following code: getLog().log(new Status(IStatus.INFO, getId(), msg)); The class is subclass of AbstractUIPlugin and parameters have following values: IStatus.INFO == 1 getId() == "AncoraPipePlugin" msg == "Plugin started: AncoraPipePlugin" Stack trace is: java.lang.NullPointerException at org.eclipse.core.internal.runtime.Log.isLoggable(Log.java:101) at org.eclipse.equinox.log.internal.ExtendedLogReaderServiceFactory.safeIsLoggable(ExtendedLogReaderServiceFactory.java:59) at org.eclipse.equinox.log.internal.ExtendedLogReaderServiceFactory.logPrivileged(ExtendedLogReaderServiceFactory.java:164) at org.eclipse.equinox.log.internal.ExtendedLogReaderServiceFactory.log(ExtendedLogReaderServiceFactory.java:150) at org.eclipse.equinox.log.internal.ExtendedLogServiceFactory.log(ExtendedLogServiceFactory.java:65) at org.eclipse.equinox.log.internal.ExtendedLogServiceImpl.log(ExtendedLogServiceImpl.java:87) at org.eclipse.equinox.log.internal.LoggerImpl.log(LoggerImpl.java:54) at org.eclipse.core.internal.runtime.Log.log(Log.java:60) at org.ub.pluginutils.AncoraAbstractPlugin.log(AncoraAbstractPlugin.java:57) ... With a little of debugging, I got that at Log.java:101, variables have the following values: PlatformLogWriter.EQUINOX_LOGGER_NAME == "org.eclipse.equinox.logger" loggerName == "org.eclipse.equinox.logger" bundle == null /**** this is generating the exception!! ***/ loggingBundle.getBundleId() == 10817 logLevel == 3 loggingBundle is instance of BundleHost As I see, the problem is the field bundle, which is null. This seems to come from a bad initialization (when Log.bundle is set). Is this possible? Log initialization in Plugin class might be done at Plugin.java:291, where InternalPlatform.getDefault().getLog(bundle) is called. It seems that this is called with bundle==null for that plugin, being bundle a field of class Plugin, which is initialized at deprecated public Plugin(IPluginDescriptor descriptor) (not used by me) or at start. Now I realize the problem!!: I called log at my overrided start method before calling super.start(), so bundle is not yet initialized. Manu Will it be fixed in 3.7.2? (In reply to comment #15) > Will it be fixed in 3.7.2? AJ, what does your error trace look like? This is how mine looks like: LogFilter.isLoggable threw a non-fatal unchecked exception as follows: java.lang.NullPointerException at org.eclipse.core.internal.runtime.Log.isLoggable(Log.java:101) at org.eclipse.equinox.log.internal.ExtendedLogReaderServiceFactory.safeIsLoggable(ExtendedLogReaderServiceFactory.java:59) at org.eclipse.equinox.log.internal.ExtendedLogReaderServiceFactory.logPrivileged(ExtendedLogReaderServiceFactory.java:164) at org.eclipse.equinox.log.internal.ExtendedLogReaderServiceFactory.log(ExtendedLogReaderServiceFactory.java:150) at org.eclipse.equinox.log.internal.ExtendedLogServiceFactory.log(ExtendedLogServiceFactory.java:65) at org.eclipse.equinox.log.internal.ExtendedLogServiceImpl.log(ExtendedLogServiceImpl.java:87) at org.eclipse.equinox.log.internal.LoggerImpl.log(LoggerImpl.java:54) at org.eclipse.core.internal.runtime.Log.log(Log.java:60) at com.spaceops.common.PluginLogger.info(PluginLogger.java:130) at gov.nasa.jsc.plato.bridge.Activator.start(Activator.java:58) at org.eclipse.osgi.framework.internal.core.BundleContextImpl$1.run(BundleContextImpl.java:711) at java.security.AccessController.doPrivileged(Native Method) at org.eclipse.osgi.framework.internal.core.BundleContextImpl.startActivator(BundleContextImpl.java:702) at org.eclipse.osgi.framework.internal.core.BundleContextImpl.start(BundleContextImpl.java:683) at org.eclipse.osgi.framework.internal.core.BundleHost.startWorker(BundleHost.java:381) at org.eclipse.osgi.framework.internal.core.AbstractBundle.start(AbstractBundle.java:299) at org.eclipse.osgi.framework.util.SecureAction.start(SecureAction.java:440) at org.eclipse.osgi.internal.loader.BundleLoader.setLazyTrigger(BundleLoader.java:268) at org.eclipse.core.runtime.internal.adaptor.EclipseLazyStarter.postFindLocalClass(EclipseLazyStarter.java:107) at org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findLocalClass(ClasspathManager.java:462) at org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.findLocalClass(DefaultClassLoader.java:216) at org.eclipse.osgi.internal.loader.BundleLoader.findLocalClass(BundleLoader.java:400) at org.eclipse.osgi.internal.loader.BundleLoader.findClassInternal(BundleLoader.java:476) at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:429) at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:417) at org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.loadClass(DefaultClassLoader.java:107) at java.lang.ClassLoader.loadClass(ClassLoader.java:247) at org.eclipse.osgi.internal.loader.BundleLoader.loadClass(BundleLoader.java:345) at org.eclipse.osgi.framework.internal.core.BundleHost.loadClass(BundleHost.java:229) at org.eclipse.osgi.framework.internal.core.AbstractBundle.loadClass(AbstractBundle.java:1207) at org.eclipse.core.internal.registry.osgi.RegistryStrategyOSGI.createExecutableExtension(RegistryStrategyOSGI.java:174) at org.eclipse.core.internal.registry.ExtensionRegistry.createExecutableExtension(ExtensionRegistry.java:905) at org.eclipse.core.internal.registry.ConfigurationElement.createExecutableExtension(ConfigurationElement.java:243) at org.eclipse.core.internal.registry.ConfigurationElementHandle.createExecutableExtension(ConfigurationElementHandle.java:55) at org.eclipse.ui.internal.WorkbenchPlugin$1.run(WorkbenchPlugin.java:268) at org.eclipse.swt.custom.BusyIndicator.showWhile(BusyIndicator.java:52) at org.eclipse.ui.internal.WorkbenchPlugin.createExtension(WorkbenchPlugin.java:264) at org.eclipse.ui.internal.EarlyStartupRunnable.getExecutableExtension(EarlyStartupRunnable.java:117) at org.eclipse.ui.internal.EarlyStartupRunnable.run(EarlyStartupRunnable.java:66) at org.eclipse.core.runtime.SafeRunner.run(SafeRunner.java:42) at org.eclipse.ui.internal.Workbench$63.run(Workbench.java:2465) at org.eclipse.core.internal.jobs.Worker.run(Worker.java:54) (In reply to comment #17) > LogFilter.isLoggable threw a non-fatal unchecked exception as follows: > java.lang.NullPointerException > at org.eclipse.core.internal.runtime.Log.isLoggable(Log.java:101) > at > org.eclipse.equinox.log.internal.ExtendedLogReaderServiceFactory.safeIsLoggable(ExtendedLogReaderServiceFactory.java:59) > at > org.eclipse.equinox.log.internal.ExtendedLogReaderServiceFactory.logPrivileged(ExtendedLogReaderServiceFactory.java:164) > at > org.eclipse.equinox.log.internal.ExtendedLogReaderServiceFactory.log(ExtendedLogReaderServiceFactory.java:150) > at > org.eclipse.equinox.log.internal.ExtendedLogServiceFactory.log(ExtendedLogServiceFactory.java:65) > at > org.eclipse.equinox.log.internal.ExtendedLogServiceImpl.log(ExtendedLogServiceImpl.java:87) > at org.eclipse.equinox.log.internal.LoggerImpl.log(LoggerImpl.java:54) > at org.eclipse.core.internal.runtime.Log.log(Log.java:60) > at com.spaceops.common.PluginLogger.info(PluginLogger.java:130) > at gov.nasa.jsc.plato.bridge.Activator.start(Activator.java:58) > at > org.eclipse.osgi.framework.internal.core.BundleContextImpl$1.run(BundleContextImpl.java:711) I suggest you check your Activator code and see if there's a method call ordering issue like what Manu described in comment 13. Moving to Platform since this could be avoided in the Log class in core.runtime. Created attachment 207755 [details]
possible fix
This fix does two things.
1) Adds an IllegalArgumentException if a null plugin object is used in the construction of a Log object.
2) In Plugin.getLog it checks to see if the bundle object is null and uses a bit of class loader magic to find the actual bundle to use as the bundle for the Log object.
DJ, Please have a look at this. I am concerned about all the usages of Plugin.bundle which may be used before Plugin.start(BundleContext) is called. I forgot to mention this - I would go with only the IAE if this bug is NOT a regression from the 3.6 release. I have not tested on 3.6 so I am not sure if this is a regression or not. Can someone confirm that this used to work for you on 3.6? Yes, it is a regression since it doesn't manifest in 3.6.2 Created attachment 207808 [details]
patch
New patch to protect against other accesses to the "bundle" field using Tom's logic and classloader magic.
|