Community
Participate
Working Groups
We've got a test crash (UI was not responsible anymore) because one from our custom contributions to the PropertyTester got NPE and this broke calls to EclipseContext.deactivate and EclipseContext.activate on part closing, so that the part was not properly disposed and our custom listeners in that half-disposed part flooded error log and made Display.readAndDispatch() unusable. The problem I see here is that NPE from our custom code was able to "slip through" evaluations and destroy the workbench state. The code in question is (order as in the stack): * org.eclipse.core.internal.expressions.Property.test(Object, Object[], Object) * org.eclipse.core.internal.expressions.TestExpression.evaluate(IEvaluationContext) * org.eclipse.ui.internal.services.EvaluationReference.evaluate() The problem with that above is that it "trusts" the contributed code which is not supposed to throw ANY exception (but obviously can :-)). I believe this code should check for runtime exceptions and convert them to CoreException's. The only question I have is if we want this to be logged or not. Original code in EvaluationReference.evaluate() *hides* all CoreException and only logs them if a debug flag is set. This would cause an issue after the proposed patch - if a runtime exception is "hidden" here, we would never notice a problem with our PropertyTester contribution. So I guess it would make sense to un-hide the CoreException in EvaluationReference.evaluate(). Example stack leading to our issue: !ENTRY org.eclipse.e4.ui.workbench 4 0 2019-03-09 06:40:13.451 !MESSAGE !STACK 0 java.lang.NullPointerException at my.company.handlers.ObjectStatePropertyTester.test(ObjectStatePropertyTester.java:34) at org.eclipse.core.internal.expressions.Property.test(Property.java:61) at org.eclipse.core.internal.expressions.TestExpression.evaluate(TestExpression.java:103) at org.eclipse.core.internal.expressions.CompositeExpression.evaluateAnd(CompositeExpression.java:55) at org.eclipse.core.internal.expressions.AdaptExpression.evaluate(AdaptExpression.java:118) at org.eclipse.core.internal.expressions.CompositeExpression.evaluateAnd(CompositeExpression.java:55) at org.eclipse.core.internal.expressions.IterateExpression.evaluate(IterateExpression.java:199) at org.eclipse.core.internal.expressions.CompositeExpression.evaluateAnd(CompositeExpression.java:55) at org.eclipse.core.internal.expressions.WithExpression.evaluate(WithExpression.java:81) at org.eclipse.core.internal.expressions.ReferenceExpression.evaluate(ReferenceExpression.java:74) at org.eclipse.core.internal.expressions.CompositeExpression.evaluateAnd(CompositeExpression.java:55) at org.eclipse.core.internal.expressions.AndExpression.evaluate(AndExpression.java:34) at org.eclipse.ui.internal.services.EvaluationReference.evaluate(EvaluationReference.java:74) at org.eclipse.ui.internal.services.EvaluationReference.evaluate(EvaluationReference.java:101) at org.eclipse.ui.internal.services.EvaluationReference.changed(EvaluationReference.java:95) at org.eclipse.e4.core.internal.contexts.TrackableComputationExt.update(TrackableComputationExt.java:117) at org.eclipse.e4.core.internal.contexts.EclipseContext.processScheduled(EclipseContext.java:365) at org.eclipse.e4.core.internal.contexts.EclipseContext.set(EclipseContext.java:380) at org.eclipse.e4.core.internal.contexts.EclipseContext.deactivate(EclipseContext.java:704) at org.eclipse.ui.part.MultiPageEditorSite.deactivate(MultiPageEditorSite.java:213) at org.eclipse.ui.part.MultiPageEditorPart.deactivateSite(MultiPageEditorPart.java:912) at org.eclipse.ui.part.MultiPageEditorPart.dispose(MultiPageEditorPart.java:502) at my.company.MultiPageXYZEditor.dispose(MultiPageXYZEditor.java:317) at org.eclipse.ui.internal.e4.compatibility.CompatibilityPart.invalidate(CompatibilityPart.java:264) at org.eclipse.ui.internal.e4.compatibility.CompatibilityPart.destroy(CompatibilityPart.java:424) Any comments? I will push a patch in a moment with proposed change.
Some AERI reports showing exceptions that are "flying through" EvaluationReference.evaluate: https://dev.eclipse.org/recommenders/committers/aeri/v2/#!/problems/575438efe4b0ecdefebe0214 https://dev.eclipse.org/recommenders/committers/aeri/v2/#!/problems/559a49c2e4b08735226ba8b0 https://dev.eclipse.org/recommenders/committers/aeri/v2/#!/problems/55c38553e4b0d6907d416160
New Gerrit change created: https://git.eclipse.org/r/138659
New Gerrit change created: https://git.eclipse.org/r/138661
(In reply to Eclipse Genie from comment #2) > New Gerrit change created: https://git.eclipse.org/r/138659 (In reply to Eclipse Genie from comment #3) > New Gerrit change created: https://git.eclipse.org/r/138661 With this two patches above we will see following in the log (if some NPE happens during property test): org.eclipse.e4.ui.workbench Error Wed Mar 13 14:51:03 CET 2019 Failed to evaluate: ReferenceExpression [definitionId=org.eclipse.ui.workbenchWindow.isPerspectiveOpen.enabledWhen] org.eclipse.core.runtime.CoreException: Error evaluating Property [org.eclipse.ui.workbenchWindow.isPerspectiveOpen, type=class org.eclipse.ui.internal.WorkbenchWindow, tester=org.eclipse.ui.internal.OpenPerspectivePropertyTester@35f7969d] at org.eclipse.core.internal.expressions.Property.test(Property.java:68) at org.eclipse.core.internal.expressions.TestExpression.evaluate(TestExpression.java:103) at org.eclipse.core.internal.expressions.CompositeExpression.evaluateAnd(CompositeExpression.java:55) at org.eclipse.core.internal.expressions.WithExpression.evaluate(WithExpression.java:81) at org.eclipse.core.internal.expressions.CompositeExpression.evaluateAnd(CompositeExpression.java:55) at org.eclipse.core.internal.expressions.AndExpression.evaluate(AndExpression.java:34) at org.eclipse.core.internal.expressions.ReferenceExpression.evaluate(ReferenceExpression.java:74) at org.eclipse.ui.internal.services.EvaluationReference.evaluate(EvaluationReference.java:74) at org.eclipse.ui.internal.services.EvaluationReference.evaluate(EvaluationReference.java:100) at org.eclipse.ui.internal.services.EvaluationReference.changed(EvaluationReference.java:94) at org.eclipse.e4.core.internal.contexts.TrackableComputationExt.update(TrackableComputationExt.java:117) at org.eclipse.e4.core.internal.contexts.EclipseContext.processScheduled(EclipseContext.java:365) at org.eclipse.e4.core.internal.contexts.EclipseContext.set(EclipseContext.java:380) at org.eclipse.ui.internal.services.EvaluationService$1.changed(EvaluationService.java:79) at org.eclipse.e4.core.internal.contexts.TrackableComputationExt.update(TrackableComputationExt.java:117) at org.eclipse.e4.core.internal.contexts.EclipseContext.processScheduled(EclipseContext.java:365) at org.eclipse.e4.core.internal.contexts.EclipseContext.set(EclipseContext.java:380) at org.eclipse.ui.internal.Workbench.createWorkbenchWindow(Workbench.java:1498) at org.eclipse.ui.internal.Workbench.openWorkbenchWindow(Workbench.java:2530) at org.eclipse.ui.internal.Workbench.getWorkbenchPage(Workbench.java:1988) at org.eclipse.ui.internal.Workbench.setReference(Workbench.java:2036) at org.eclipse.ui.internal.Workbench.lambda$11(Workbench.java:1927) at org.eclipse.e4.ui.services.internal.events.UIEventHandler.lambda$0(UIEventHandler.java:38) at org.eclipse.swt.widgets.Synchronizer.syncExec(Synchronizer.java:236) at org.eclipse.ui.internal.UISynchronizer.syncExec(UISynchronizer.java:147) at org.eclipse.swt.widgets.Display.syncExec(Display.java:5999) at org.eclipse.e4.ui.internal.workbench.swt.E4Application$1.syncExec(E4Application.java:219) at org.eclipse.e4.ui.services.internal.events.UIEventHandler.handleEvent(UIEventHandler.java:38) at org.eclipse.equinox.internal.event.EventHandlerWrapper.handleEvent(EventHandlerWrapper.java:205) at org.eclipse.equinox.internal.event.EventHandlerTracker.dispatchEvent(EventHandlerTracker.java:203) at org.eclipse.equinox.internal.event.EventHandlerTracker.dispatchEvent(EventHandlerTracker.java:1) at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:233) at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:151) at org.eclipse.equinox.internal.event.EventAdminImpl.dispatchEvent(EventAdminImpl.java:132) at org.eclipse.equinox.internal.event.EventAdminImpl.sendEvent(EventAdminImpl.java:75) at org.eclipse.equinox.internal.event.EventComponent.sendEvent(EventComponent.java:44) at org.eclipse.e4.ui.services.internal.events.EventBroker.send(EventBroker.java:55) at org.eclipse.e4.ui.internal.workbench.UIEventPublisher.notifyChanged(UIEventPublisher.java:63) at org.eclipse.emf.common.notify.impl.BasicNotifierImpl.eNotify(BasicNotifierImpl.java:424) at org.eclipse.e4.ui.model.application.ui.basic.impl.PartImpl.setContext(PartImpl.java:459) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.safeCreateGui(PartRenderingEngine.java:650) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine$1.run(PartRenderingEngine.java:560) at org.eclipse.core.runtime.SafeRunner.run(SafeRunner.java:45) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.createGui(PartRenderingEngine.java:544) at org.eclipse.e4.ui.workbench.renderers.swt.ElementReferenceRenderer.createWidget(ElementReferenceRenderer.java:73) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.createWidget(PartRenderingEngine.java:1015) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.safeCreateGui(PartRenderingEngine.java:675) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.safeCreateGui(PartRenderingEngine.java:781) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.access$0(PartRenderingEngine.java:752) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine$2.run(PartRenderingEngine.java:746) at org.eclipse.core.runtime.SafeRunner.run(SafeRunner.java:45) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.createGui(PartRenderingEngine.java:730) at org.eclipse.e4.ui.workbench.renderers.swt.StackRenderer.showTab(StackRenderer.java:1295) at org.eclipse.e4.ui.workbench.renderers.swt.LazyStackRenderer.postProcess(LazyStackRenderer.java:105) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.safeCreateGui(PartRenderingEngine.java:693) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.safeCreateGui(PartRenderingEngine.java:781) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.access$0(PartRenderingEngine.java:752) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine$2.run(PartRenderingEngine.java:746) at org.eclipse.core.runtime.SafeRunner.run(SafeRunner.java:45) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.createGui(PartRenderingEngine.java:730) at org.eclipse.e4.ui.workbench.renderers.swt.SWTPartRenderer.processContents(SWTPartRenderer.java:72) at org.eclipse.e4.ui.workbench.renderers.swt.SashRenderer.processContents(SashRenderer.java:140) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.safeCreateGui(PartRenderingEngine.java:689) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.safeCreateGui(PartRenderingEngine.java:781) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.access$0(PartRenderingEngine.java:752) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine$2.run(PartRenderingEngine.java:746) at org.eclipse.core.runtime.SafeRunner.run(SafeRunner.java:45) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.createGui(PartRenderingEngine.java:730) at org.eclipse.e4.ui.workbench.renderers.swt.SWTPartRenderer.processContents(SWTPartRenderer.java:72) at org.eclipse.e4.ui.workbench.renderers.swt.SashRenderer.processContents(SashRenderer.java:140) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.safeCreateGui(PartRenderingEngine.java:689) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.safeCreateGui(PartRenderingEngine.java:781) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.access$0(PartRenderingEngine.java:752) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine$2.run(PartRenderingEngine.java:746) at org.eclipse.core.runtime.SafeRunner.run(SafeRunner.java:45) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.createGui(PartRenderingEngine.java:730) at org.eclipse.e4.ui.workbench.renderers.swt.SWTPartRenderer.processContents(SWTPartRenderer.java:72) at org.eclipse.e4.ui.workbench.renderers.swt.PerspectiveRenderer.processContents(PerspectiveRenderer.java:51) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.safeCreateGui(PartRenderingEngine.java:689) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.safeCreateGui(PartRenderingEngine.java:781) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.access$0(PartRenderingEngine.java:752) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine$2.run(PartRenderingEngine.java:746) at org.eclipse.core.runtime.SafeRunner.run(SafeRunner.java:45) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.createGui(PartRenderingEngine.java:730) at org.eclipse.e4.ui.workbench.renderers.swt.PerspectiveStackRenderer.showTab(PerspectiveStackRenderer.java:82) at org.eclipse.e4.ui.workbench.renderers.swt.LazyStackRenderer.postProcess(LazyStackRenderer.java:105) at org.eclipse.e4.ui.workbench.renderers.swt.PerspectiveStackRenderer.postProcess(PerspectiveStackRenderer.java:64) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.safeCreateGui(PartRenderingEngine.java:693) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.safeCreateGui(PartRenderingEngine.java:781) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.access$0(PartRenderingEngine.java:752) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine$2.run(PartRenderingEngine.java:746) at org.eclipse.core.runtime.SafeRunner.run(SafeRunner.java:45) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.createGui(PartRenderingEngine.java:730) at org.eclipse.e4.ui.workbench.renderers.swt.SWTPartRenderer.processContents(SWTPartRenderer.java:72) at org.eclipse.e4.ui.workbench.renderers.swt.SashRenderer.processContents(SashRenderer.java:140) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.safeCreateGui(PartRenderingEngine.java:689) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.safeCreateGui(PartRenderingEngine.java:781) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.access$0(PartRenderingEngine.java:752) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine$2.run(PartRenderingEngine.java:746) at org.eclipse.core.runtime.SafeRunner.run(SafeRunner.java:45) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.createGui(PartRenderingEngine.java:730) at org.eclipse.e4.ui.workbench.renderers.swt.SWTPartRenderer.processContents(SWTPartRenderer.java:72) at org.eclipse.e4.ui.workbench.renderers.swt.WBWRenderer.processContents(WBWRenderer.java:665) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.safeCreateGui(PartRenderingEngine.java:689) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.safeCreateGui(PartRenderingEngine.java:781) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.access$0(PartRenderingEngine.java:752) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine$2.run(PartRenderingEngine.java:746) at org.eclipse.core.runtime.SafeRunner.run(SafeRunner.java:45) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.createGui(PartRenderingEngine.java:730) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine$5.run(PartRenderingEngine.java:1099) at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:338) at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.run(PartRenderingEngine.java:1062) at org.eclipse.e4.ui.internal.workbench.E4Workbench.createAndRunUI(E4Workbench.java:155) at org.eclipse.ui.internal.Workbench.lambda$3(Workbench.java:644) at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:338) at org.eclipse.ui.internal.Workbench.createAndRunWorkbench(Workbench.java:566) at org.eclipse.ui.PlatformUI.createAndRunWorkbench(PlatformUI.java:150) at org.eclipse.ui.internal.ide.application.IDEApplication.start(IDEApplication.java:155) at org.eclipse.equinox.internal.app.EclipseAppHandle.run(EclipseAppHandle.java:203) at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.runApplication(EclipseAppLauncher.java:137) at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.start(EclipseAppLauncher.java:107) at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:400) at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:255) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:566) at org.eclipse.equinox.launcher.Main.invokeFramework(Main.java:661) at org.eclipse.equinox.launcher.Main.basicRun(Main.java:597) at org.eclipse.equinox.launcher.Main.run(Main.java:1476) at org.eclipse.equinox.launcher.Main.main(Main.java:1449) Caused by: java.lang.NullPointerException: OMG at org.eclipse.ui.internal.OpenPerspectivePropertyTester.test(OpenPerspectivePropertyTester.java:35) at org.eclipse.core.internal.expressions.Property.test(Property.java:65) ... 130 more
Gerrit change https://git.eclipse.org/r/138659 was merged to [master]. Commit: http://git.eclipse.org/c/platform/eclipse.platform.runtime.git/commit/?id=def768d7c489244820fb26c597f122f675646d00
Gerrit change https://git.eclipse.org/r/138661 was merged to [master]. Commit: http://git.eclipse.org/c/platform/eclipse.platform.ui.git/commit/?id=64d6e13fbf08b37e6b5072c15f8543c3d50511fc
Always logging CoreExceptions in EvaluationReference is probably not a good idea, because it now makes all sorts of Exceptions visible that do not happen in the actual PropertyTester invocation, but those that are thrown from the framework in TypeExtensionManager.getProperty(), in case, for example, a matching propety tester cannot be found. This change can lead to large amounts of the following error log entries being written now: org.eclipse.core.runtime.CoreException: No property tester contributes a property com.foo.bar.baz to type class org.eclipse.core.internal.resources.Project at org.eclipse.core.internal.expressions.TypeExtensionManager.getProperty(TypeExtensionManager.java:130) at org.eclipse.core.internal.expressions.TestExpression.evaluate(TestExpression.java:100) at org.eclipse.core.internal.expressions.CompositeExpression.evaluateAnd(CompositeExpression.java:55) at org.eclipse.core.internal.expressions.IterateExpression.evaluate(IterateExpression.java:165) at org.eclipse.core.internal.expressions.CompositeExpression.evaluateAnd(CompositeExpression.java:55) at org.eclipse.core.internal.expressions.AndExpression.evaluate(AndExpression.java:34) ... I think we shouldn't just make such framework Exceptions visible so prominently now without a proper rollout / news-and-noteworthy. Also, for symmetry reasons: There are many more places where Policy.DEBUG_CMDS is queried first for such CoreExceptions: - org.eclipse.e4.ui.internal.workbench.ContributionsAnalyzer.isCoreExpressionVisible(MCoreExpression, ExpressionContext) - org.eclipse.ui.internal.handlers.HandlerActivation.evaluate(IEvaluationContext) - ... All these places share the same pattern: - They catch a potential CoreException thrown by the framework itself... - ... and only trace it if Policy.DEBUG_CMDS is enabled. This is reasonable, because while such property testers registrations could easily be fixed to not run into such an exception in the first place, it really doesn't do any harm. Instead, I propose to just treat the PropertyTesters specially and restoring the old Policy.DEBUG_CMDS behavior, so we can distinguish between: a) The regular CoreException thrown from TypeExtensionManager if the property tester cannot be found b) A RuntimeException that happens *inside* the implementation of such a property tester. I will add a Gerrit change with a suggestion.
New Gerrit change created: https://git.eclipse.org/r/141970
New Gerrit change created: https://git.eclipse.org/r/141971
@Andrey Loskutov: Could you have a look at my proposed patches?
(In reply to Sebastian Ratz from comment #10) > @Andrey Loskutov: > Could you have a look at my proposed patches? Sebastian, please provide example to see the errors you have mentioned in comment 7.
(In reply to Sebastian Ratz from comment #7) > Always logging CoreExceptions in EvaluationReference is probably not a good > idea, because it now makes all sorts of Exceptions visible that do not > happen in the actual PropertyTester invocation, but those that are thrown > from the framework in TypeExtensionManager.getProperty(), in case, for > example, a matching propety tester cannot be found. > > This change can lead to large amounts of the following error log entries > being written now: > > org.eclipse.core.runtime.CoreException: No property tester contributes a > property com.foo.bar.baz to type class > org.eclipse.core.internal.resources.Project Question: why is this wrong to log this error? It is a bug if the code references not existing tester property (either the tester contribution or the contribution using tester are buggy), and it would be not visible with your patch. Means: the code will not properly evaluate, some contribution will "silently" be broken and developers will spent hours to understand where some feature XYZ can be broken.
(In reply to Andrey Loskutov from comment #12) > (In reply to Sebastian Ratz from comment #7) > > Always logging CoreExceptions in EvaluationReference is probably not a good > > idea, because it now makes all sorts of Exceptions visible that do not > > happen in the actual PropertyTester invocation, but those that are thrown > > from the framework in TypeExtensionManager.getProperty(), in case, for > > example, a matching propety tester cannot be found. > > > > This change can lead to large amounts of the following error log entries > > being written now: > > > > org.eclipse.core.runtime.CoreException: No property tester contributes a > > property com.foo.bar.baz to type class > > org.eclipse.core.internal.resources.Project > > Question: why is this wrong to log this error? I am not saying it is, just that: 1) It previously was *not* logged, only traced. And changing it now can lead to potential massive amounts of log entries that previously were not noticed by the user (which could and should be fixed, but are actually harmless, see my example above). 2) For consistency with org.eclipse.e4.ui.internal.workbench.ContributionsAnalyzer.isCoreExpressionVisible(MCoreExpression, ExpressionContext) and org.eclipse.ui.internal.handlers.HandlerActivation.evaluate(IEvaluationContext) it seems wrong to me, to just change it in one place. > It is a bug if the code references not existing tester property (either the > tester contribution or the contribution using tester are buggy), and it > would be not visible with your patch. It would, if tracing is on. And yes, that is exactly the problem: There are many such "broken" property tester expressions out there. None of those mistakes were visible before, but there also was no harm. Changing it to logging now would make them all visible, suddenly. > Means: the code will not properly evaluate, some contribution will > "silently" be broken and developers will spent hours to understand where > some feature XYZ can be broken. I agree. It would be nice if all those places I listed above would use logging by default. But changing this feels like something that should be announced as a "incompatible" future change for the reason above, with some lead time for consumers to make adjustments.
(In reply to Sebastian Ratz from comment #13) > (In reply to Andrey Loskutov from comment #12) > > Question: why is this wrong to log this error? > > I am not saying it is, just that: > 1) It previously was *not* logged, only traced. And changing it now can lead > to potential massive amounts of log entries that previously were not noticed > by the user (which could and should be fixed, but are actually harmless, see > my example above). You never know what is harmless and what not... I think every wrong contribution deserves an error log entry and should not be silently ignored, because we (as platform) can't know how critical it could be to the end user, see comment 0 with one example, and we also know how much time one can spend trying to find an error that was silently ignored. > 2) For consistency with > org.eclipse.e4.ui.internal.workbench.ContributionsAnalyzer. > isCoreExpressionVisible(MCoreExpression, ExpressionContext) and > org.eclipse.ui.internal.handlers.HandlerActivation. > evaluate(IEvaluationContext) > it seems wrong to me, to just change it in one place. I haven't checked this code yet, but feel free to open a new bug for this and provide a Gerrit. > > Means: the code will not properly evaluate, some contribution will > > "silently" be broken and developers will spent hours to understand where > > some feature XYZ can be broken. > I agree. It would be nice if all those places I listed above would use > logging by default. But changing this feels like something that should be > announced as a "incompatible" future change for the reason above, with some > lead time for consumers to make adjustments. It can't be incompatible because it does not break any contract, it is just flagging "bad" contribution with errors in the log. For example if we fix something in compiler that was broken before it may cause "bad" code at consumers to be not compilable anymore (see for example bug 525822 comment 14) - but not fixing it is to break *good* consumers relying on a correct behavior and correct error reporting. Those consumers who have unknown "bad" contributions can always fix them first, before upgrading the platform - they aren't forced to upgrade.
(In reply to Andrey Loskutov from comment #14) > (In reply to Sebastian Ratz from comment #13) > > (In reply to Andrey Loskutov from comment #12) > > > Question: why is this wrong to log this error? > > > > I am not saying it is, just that: > > 1) It previously was *not* logged, only traced. And changing it now can lead > > to potential massive amounts of log entries that previously were not noticed > > by the user (which could and should be fixed, but are actually harmless, see > > my example above). > > You never know what is harmless and what not... I think every wrong > contribution deserves an error log entry and should not be silently ignored, > because we (as platform) can't know how critical it could be to the end > user, see comment 0 with one example, and we also know how much time one can > spend trying to find an error that was silently ignored. > > > 2) For consistency with > > org.eclipse.e4.ui.internal.workbench.ContributionsAnalyzer. > > isCoreExpressionVisible(MCoreExpression, ExpressionContext) and > > org.eclipse.ui.internal.handlers.HandlerActivation. > > evaluate(IEvaluationContext) > > it seems wrong to me, to just change it in one place. > > I haven't checked this code yet, but feel free to open a new bug for this > and provide a Gerrit. > > > > Means: the code will not properly evaluate, some contribution will > > > "silently" be broken and developers will spent hours to understand where > > > some feature XYZ can be broken. > > I agree. It would be nice if all those places I listed above would use > > logging by default. But changing this feels like something that should be > > announced as a "incompatible" future change for the reason above, with some > > lead time for consumers to make adjustments. > > It can't be incompatible because it does not break any contract, it is just > flagging "bad" contribution with errors in the log. > > For example if we fix something in compiler that was broken before it may > cause "bad" code at consumers to be not compilable anymore (see for example > bug 525822 comment 14) - but not fixing it is to break *good* consumers > relying on a correct behavior and correct error reporting. > > Those consumers who have unknown "bad" contributions can always fix them > first, before upgrading the platform - they aren't forced to upgrade. I agree with your points, but it still feels wrong to just convert the trace into a log unconditionally. See for example the comment in https://github.com/eclipse/eclipse.platform.ui/blob/3cf23b7d8b0fc4e57f18118cb6fc92a8e6de0490/bundles/org.eclipse.ui.workbench/Eclipse%20UI/org/eclipse/ui/internal/handlers/HandlerActivation.java#L94 /* * Swallow the exception. It simply means the variable is not valid (most * frequently, that the value is null or has a complex core expression with a * property tester). This kind of information is not really useful to us, so we * can just treat it as false. */ The same applies to EvaluationReference. Wit the change https://git.eclipse.org/r/#/c/138661/ this might now make such scenarios visible with an error. I think Policy.DEBUG_CMD and trace-only was introduced with exactly that in mind and converting it to an unconditional error log seems wrong to me.
Created attachment 278767 [details] Error log from 2019-06 Ok, so I updated my main development IDE to 2019-06 I-build now. And as expected/feared, I now get hundreds and hundreds of exceptions that were hidden before. See attachment. Some examples: - org.eclipse.core.runtime.CoreException: No property tester contributes a property org.eclipse.jdt.launching.jdtstratum to type class org.eclipse.ui.internal.views.log.LogEntry - org.eclipse.core.runtime.CoreException: No property tester contributes a property org.eclipse.core.resources.projectNature to type class org.eclipse.jdt.internal.core.CompilationUnit - org.eclipse.core.runtime.CoreException: No property tester contributes a property org.eclipse.jdt.launching.jdtstratum to type class org.eclipse.jdt.internal.core.CompilationUnit - org.eclipse.core.runtime.CoreException: No property tester contributes a property org.eclipse.jdt.launching.jdtstratum to type class org.eclipse.egit.ui.internal.repository.tree.RefNode All of those *could* be fixed by the respective plugins. But: - They are harmless! They are thrown as CoreExceptions by the expression framework in order to get stack information. But the are intentionally hidden by trace-only! - This affects a multitude of projects in simrel. Your argument '"bad" contributions can always fix them first, before upgrading the platform - they aren't forced to upgrade' does not apply IMHO. Polluted error logs such as this really shed a bad light on the whole Eclipse project, therefore I would urge for my two gerrit changes to be merged for 2019-06: - It still solves the original problem with client code throwing RuntimeExceptions. - It reverts the problematic change from trace to log. This is simply too dangerous to just do it alongside the other change without a whole picture of all the implications.
(In reply to Sebastian Ratz from comment #16) > Polluted error logs such as this really shed a bad light on the whole > Eclipse project, therefore I would urge for my two gerrit changes to be > merged for 2019-06: > - It still solves the original problem with client code throwing > RuntimeExceptions. > - It reverts the problematic change from trace to log. This is simply too > dangerous to just do it alongside the other change without a whole picture > of all the implications. I had luck not to use org.eclipse.m2e and except this one I do not see any other "bad" clients in your log. So please open a bug for m2e and ask them to fix the wrong contribution for 4.12, this should be doable. If you want the platform to fix the reporting, open a dedicated bug for this. PS: I'm using IDE based on DLTK, CDT, Webtools, GEF, Xtext, and many other plugins - with not a single error reported.
This was just one example, I am pretty sure there will be more issues besides m2e. Especially for third-party plugins. And again, "noone forces them to adopt 2019-06" is not a good attitude in my opinion. The original goal of this bug was to prevent client code exceptions leaking into the framework. This can be fixed completely independently from any changes to the framework itself. I fail to understand *WHY* this change to the framework is so important that it needs to be done now alongside this fix. And if it actually is so important then I would all the more propose to do it properly in a separate change - with all the concerns addressed - and not last-minute for RC1.
(In reply to Sebastian Ratz from comment #18) > The original goal of this bug was to prevent client code exceptions leaking > into the framework. Yes. Therefore if you see a side effect, please open a bug describing the concrete problem. > I fail to understand *WHY* this change to the framework is so important that > it needs to be done now alongside this fix. I'm not saying this is important, I just fail to understand what is wrong with the change... So far your arguments were not convincing. > And if it actually is so important then I would all the more propose to do > it properly in a separate change - with all the concerns addressed - and not > last-minute for RC1. I don't get this. The change here went into M1, not "last minute" RC1. This discussion seem never end. Sebastian, please, could you just do what I've asked before? Create a bug for m2e. From my POV this is m2e problem in first place, they seem to add expression with org.eclipse.jdt.launching.jdtstratum test for *any* object, not only for org.eclipse.debug.core.model.DebugElement, see https://git.eclipse.org/r/#/c/122830/9/org.eclipse.m2e.sourcelookup.ui/plugin.xml. This is a bug and should be fixed.
(In reply to Andrey Loskutov from comment #19) > This discussion seem never end. Sebastian, please, could you just do what > I've asked before? Create a bug for m2e. I did it for you: see bug 547760.
I agree here with Sebastian. M2e is widely used and logging errors which were previously only traced gives a bad impression for the users of our IDE. I suggest to change logging back to tracing until the bug in m2e is fixed. Also https://bugs.eclipse.org/bugs/show_bug.cgi?id=545270#c16 says that we have issues with JDT, EGit and Resources. If these issues still exists, they should also be fixed before we switch to logging. Dani, WDYT?
Reopen for the discussion.
(In reply to Lars Vogel from comment #22) > Reopen for the discussion. Couldn't we have a dedicated bug for a discussion?
(In reply to Andrey Loskutov from comment #23) > (In reply to Lars Vogel from comment #22) > > Reopen for the discussion. > > Couldn't we have a dedicated bug for a discussion? Looks to me that this is this bug. It introduced the change and has the reverts attached.
(In reply to Lars Vogel from comment #21) > I agree here with Sebastian. M2e is widely used and logging errors which > were previously only traced gives a bad impression for the users of our IDE. > > I suggest to change logging back to tracing until the bug in m2e is fixed. It should be fixed now, see bug 547760. I really suggest to open a dedicated bug for a discussion how we should threat expression contributions with errors, and leave this bug for the original problem, which is fixed. IMHO bad contribution that internally generates lot of exceptions but not logged (and so not noticed by anyone) is worse than the same contribution identified and fixed. So till now no one noticed that m2e probably slows down selections in IDE due wrong contribution because we never reported that.
(In reply to Andrey Loskutov from comment #25) > (In reply to Lars Vogel from comment #21) > > I agree here with Sebastian. M2e is widely used and logging errors which > > were previously only traced gives a bad impression for the users of our IDE. > > > > I suggest to change logging back to tracing until the bug in m2e is fixed. > > It should be fixed now, see bug 547760. > > I really suggest to open a dedicated bug for a discussion how we should > threat expression contributions with errors, and leave this bug for the > original problem, which is fixed. Absolutely. But like stated above: In this bug we should *only* fix this bug and revert the changes to the framework for now. In the new bug we can then discuss whether Log->Trace is a good idea and then maybe re-introduce the framework change. > IMHO bad contribution that internally generates lot of exceptions but not > logged (and so not noticed by anyone) is worse than the same contribution > identified and fixed. So till now no one noticed that m2e probably slows > down selections in IDE due wrong contribution because we never reported that. Again, the javadoc I linked above has exactly that in mind and it was still decided to only trace such information. Re-thinking this is exactly the discussion that would belong in the new bug report.
+1 for revert for 4.12. I agree with you Andrey in general but good logging but Sap is also a huge adapter of the IDE and I think we should try to help them as much as possible. Please wait to see what Dani think before closing the bug. This reached PMC level.
(In reply to Lars Vogel from comment #27) > +1 for revert for 4.12. > > I agree with you Andrey in general but good logging but Sap is also a huge > adapter of the IDE and I think we should try to help them as much as > possible. Hiding obvious programming errors is not helping them. If SAP sees this as help, I'm happy not being a user of SAP software. > Please wait to see what Dani think before closing the bug. This reached PMC > level. This bug is not about logging. The main issue was fixed, and therefore it should be closed. The second, not essential part of the patch is what we are discussing here all the time back and forth and I would really appreciate if we separate apples from oranges and create a new bug dedicated to problems with logging errors.
Let's see what Dani thinks.
(In reply to Lars Vogel from comment #27) > +1 for revert for 4.12. > > +1 for revert for 4.12. and to reapply for 4.13 as soon as master opens.
I agree with Andrey here. Of course there are many other places that could get similar love but let's not use that to prevent fixing things step by step. A revert would be appropriate if such a change was made in RC1 or even M3, but it went in early M1 on March 13. So, my vote is to leave things as is and track potential issues in new bugs. Thanks Andrey for fixing the m2e issue so quickly. As a side note I would like to point out that many developers either don't know about tracing or if they do, don't know how to correctly enable it. I suggest to send a note to cross-project-issues-dev telling that projects should watch out for this when they do their M3 testing this week.
I filed bug 566400 for a proposed workaround on the possible effects of this fix.
I have attached an example project that exposes the flooding of the error log. The coding in the plugin is valid (I hope). It contains a handler for a command with a enablement using a property tester. I have seen flooding in different plugins and RCP applications, including our plugins. The exception is thrown in TypeExtensionManager#getProperty(Object, String, String, boolean) Instructions: 1. Start naked Eclipse SDK 2. Import existing project into ws 3. Open manifest.mf 4. Press "Launch an eclipse application" (green button in manifest toolbar) In the started eclipse: 5. Open the error log and dock it in the editor area 6. Open the console, open the OSGi console 7. Find the bundle for the project and start it 8. Switch between views and see the flooding of the error log See instruction in attached movie.
Created attachment 284085 [details] Project with handler enablement and property tester
Created attachment 284086 [details] Instructions and symptom
New Gerrit change created: https://git.eclipse.org/r/c/platform/eclipse.platform.ui/+/169032
(In reply to Eclipse Genie from comment #36) > New Gerrit change created: > https://git.eclipse.org/r/c/platform/eclipse.platform.ui/+/169032 See comment 28. Please don't reuse this bug, it was *not* about logging. Please create new one regarding *logging*, and let discuss there if the new example from comment 34 is valid or not.
(In reply to Andrey Loskutov from comment #37) > > Please don't reuse this bug, it was *not* about logging. Please create new > one regarding *logging*, and let discuss there if the new example from > comment 34 is valid or not. Apologies. I have filed bug 566814 with a problem description, how to provoke the issue in a valid configuration, and a solution to mitigate the flooding.
This bug is causing a lot of console log flooding issues. I finally figured out why this fix is flawed: If there is an enabledwhen evaluation with an 'AND' construct, it actually matters how the 'AND' is constructed in the plugin.xml I have an enabledWhen expression that must fire on a activePartID AND a value from a property tester. If I put the propertyTester as the first AND argument, the log is flooded, if I put the propertyTester as the last argument then there is no log flooding. Attached an example.
Created attachment 284775 [details] Example plugin
(In reply to Wim Jongman from comment #39) > This bug is causing a lot of console log flooding issues. I believe you had already created bug 566814 for that? If even after the fix for bug 566814 the problem is still there, please do not reuse this bug again, but create a new one.
