Bugzilla – Full Text Bug Listing
| Summary: | IAE during setRawClasspath(..) due to missing link to external | ||
|---|---|---|---|
| Product: | [Eclipse Project] Platform | Reporter: | Stephan Herrmann <stephan.herrmann> |
| Component: | Resources | Assignee: | Szymon Brandys <Szymon.Brandys> |
| Status: | RESOLVED FIXED | QA Contact: | |
| Severity: | normal | ||
| Priority: | P3 | CC: | andrew.eisenberg, carsten.hammer, daniel_megert, jarthana, john.arthorne, kdevolder, markus.kell.r, satyam.kandula, sptaszkiewicz, srikanth_sankaran, stefan.schedl, Szymon.Brandys |
| Version: | 3.8 | Flags: | sptaszkiewicz:
review+
john.arthorne: review+ |
| Target Milestone: | 3.8 RC2 | ||
| Hardware: | PC | ||
| OS: | Linux | ||
| Whiteboard: | |||
| Bug Depends on: | 244315 | ||
| Bug Blocks: | |||
| Attachments: | |||
For an occurrence in regular JDT tests see http://download.eclipse.org/eclipse/downloads/drops/I20111230-0735/testresults/html/org.eclipse.jdt.core.tests.model_macosx.cocoa.x86_5.0.html For investigation please use the following stack trace (the OT variant has slightly different line numbers in JavaProject): Element not found: /.org.eclipse.jdt.core.external.folders/.link13. java.lang.IllegalArgumentException: Element not found: /.org.eclipse.jdt.core.external.folders/.link13. at org.eclipse.core.internal.watson.ElementTree.elementNotFound(ElementTree.java:256) at org.eclipse.core.internal.watson.ElementTree.createElement(ElementTree.java:184) at org.eclipse.core.internal.resources.Workspace.createResource(Workspace.java:1369) at org.eclipse.core.internal.resources.Workspace.createResource(Workspace.java:1322) at org.eclipse.core.internal.localstore.RefreshLocalVisitor.createResource(RefreshLocalVisitor.java:80) at org.eclipse.core.internal.localstore.RefreshLocalAliasVisitor.createResource(RefreshLocalAliasVisitor.java:38) at org.eclipse.core.internal.localstore.RefreshLocalVisitor.synchronizeExistence(RefreshLocalVisitor.java:219) at org.eclipse.core.internal.localstore.RefreshLocalVisitor.visit(RefreshLocalVisitor.java:293) at org.eclipse.core.internal.localstore.UnifiedTree.accept(UnifiedTree.java:110) at org.eclipse.core.internal.localstore.FileSystemResourceManager.refreshResource(FileSystemResourceManager.java:920) at org.eclipse.core.internal.localstore.FileSystemResourceManager.refresh(FileSystemResourceManager.java:904) at org.eclipse.core.internal.resources.Resource.refreshLocal(Resource.java:1694) at org.eclipse.core.internal.resources.Resource.createLink(Resource.java:711) at org.eclipse.core.internal.resources.Resource.createLink(Resource.java:647) at org.eclipse.jdt.internal.core.ExternalFoldersManager.createLinkFolder(ExternalFoldersManager.java:153) at org.eclipse.jdt.internal.core.ExternalFoldersManager.createLinkFolder(ExternalFoldersManager.java:145) at org.eclipse.jdt.internal.core.ExternalFolderChange.updateExternalFoldersIfNecessary(ExternalFolderChange.java:48) at org.eclipse.jdt.internal.core.ChangeClasspathOperation.classpathChanged(ChangeClasspathOperation.java:62) at org.eclipse.jdt.internal.core.SetClasspathOperation.executeOperation(SetClasspathOperation.java:74) at org.eclipse.jdt.internal.core.JavaModelOperation.run(JavaModelOperation.java:728) at org.eclipse.core.internal.resources.Workspace.run(Workspace.java:2344) at org.eclipse.jdt.internal.core.JavaModelOperation.runOperation(JavaModelOperation.java:793) at org.eclipse.jdt.internal.core.JavaProject.setRawClasspath(JavaProject.java:3095) at org.eclipse.jdt.internal.core.JavaProject.setRawClasspath(JavaProject.java:3057) at org.eclipse.jdt.internal.core.JavaProject.setRawClasspath(JavaProject.java:3069) at org.eclipse.jdt.core.tests.model.AbstractJavaModelTests$4.run(AbstractJavaModelTests.java:1638) at org.eclipse.core.internal.resources.Workspace.run(Workspace.java:2344) at org.eclipse.core.internal.resources.Workspace.run(Workspace.java:2326) at org.eclipse.jdt.core.tests.model.AbstractJavaModelTests.createJavaProject(AbstractJavaModelTests.java:1658) at org.eclipse.jdt.core.tests.model.AbstractJavaModelTests.createJavaProject(AbstractJavaModelTests.java:1268) at org.eclipse.jdt.core.tests.model.AttachSourceTests.testExternalFolder5(AttachSourceTests.java:506) *** Bug 367221 has been marked as a duplicate of this bug. *** I actually see this exception quite frequently, both in Object Teams builds and also in official Eclipse SDK builds. This occurred again in the last nightly build (N20120210-2000). Stephan, since you said you see this in your environment, may I ask for some help in terms of additional information if the failure occurs again? The things I am looking for are: whether it's the same resource (what you mentioned earlier) that has trouble all the time, whether or not the resource being linked exists, contents of the external folders project's .project file etc. I'm not sure the bug let's me get that close that I could answer your questions first hand. I suggest we design some test harness that should log the desired information, when it happens again during testing, what do you think? (In reply to comment #5) > I suggest we design some test harness that should log the desired information, > when it happens again during testing, what do you think? Makes sense. I will add some debugging information to the failing test. Added some debugging code in case the test fails again. Hopefully this will reveal what's going on. (In reply to comment #7) > Added some debugging code in case the test fails again. Hopefully this will > reveal what's going on. For the record, it's here: http://git.eclipse.org/c/jdt/eclipse.jdt.core.git/commit/?id=189e4902a8cd4c72cdcb57f23d61ddb627236e43 We also get this occasionally in JDT/UI tests, mostly on Linux. This time, it was FatJarExportTests.testExternalClassFolder in I20120223-0928. Bug 244315 is a Platform/Resources bug for the same issue. java.lang.IllegalArgumentException: Element not found: /.org.eclipse.jdt.core.external.folders/.link0. at org.eclipse.core.internal.watson.ElementTree.elementNotFound(ElementTree.java:256) at org.eclipse.core.internal.watson.ElementTree.createElement(ElementTree.java:184) at org.eclipse.core.internal.resources.Workspace.createResource(Workspace.java:1369) at org.eclipse.core.internal.resources.Workspace.createResource(Workspace.java:1322) at org.eclipse.core.internal.localstore.RefreshLocalVisitor.createResource(RefreshLocalVisitor.java:80) at org.eclipse.core.internal.localstore.RefreshLocalAliasVisitor.createResource(RefreshLocalAliasVisitor.java:38) at org.eclipse.core.internal.localstore.RefreshLocalVisitor.synchronizeExistence(RefreshLocalVisitor.java:219) at org.eclipse.core.internal.localstore.RefreshLocalVisitor.visit(RefreshLocalVisitor.java:293) at org.eclipse.core.internal.localstore.UnifiedTree.accept(UnifiedTree.java:110) at org.eclipse.core.internal.localstore.FileSystemResourceManager.refreshResource(FileSystemResourceManager.java:920) at org.eclipse.core.internal.localstore.FileSystemResourceManager.refresh(FileSystemResourceManager.java:904) at org.eclipse.core.internal.resources.Resource.refreshLocal(Resource.java:1694) at org.eclipse.core.internal.resources.Resource.createLink(Resource.java:711) at org.eclipse.core.internal.resources.Resource.createLink(Resource.java:647) at org.eclipse.jdt.internal.core.ExternalFoldersManager.createLinkFolder(ExternalFoldersManager.java:153) at org.eclipse.jdt.internal.core.ExternalFoldersManager.createLinkFolder(ExternalFoldersManager.java:145) at org.eclipse.jdt.internal.core.ExternalFolderChange.updateExternalFoldersIfNecessary(ExternalFolderChange.java:48) at org.eclipse.jdt.internal.core.ChangeClasspathOperation.classpathChanged(ChangeClasspathOperation.java:62) at org.eclipse.jdt.internal.core.SetClasspathOperation.executeOperation(SetClasspathOperation.java:74) at org.eclipse.jdt.internal.core.JavaModelOperation.run(JavaModelOperation.java:728) at org.eclipse.core.internal.resources.Workspace.run(Workspace.java:2344) at org.eclipse.jdt.internal.core.JavaModelOperation.runOperation(JavaModelOperation.java:793) at org.eclipse.jdt.internal.core.JavaProject.setRawClasspath(JavaProject.java:3095) at org.eclipse.jdt.internal.core.JavaProject.setRawClasspath(JavaProject.java:3057) at org.eclipse.jdt.internal.core.JavaProject.setRawClasspath(JavaProject.java:3110) at org.eclipse.jdt.testplugin.JavaProjectHelper.addToClasspath(JavaProjectHelper.java:738) at org.eclipse.jdt.testplugin.JavaProjectHelper.addLibrary(JavaProjectHelper.java:504) at org.eclipse.jdt.ui.tests.jarexport.FatJarExportTests.testExternalClassFolder(FatJarExportTests.java:981) This bug manifested itself in today's nightly build (N20120227-2000) again. I had put in some code to debug. But unfortunately, it's a different test that failed this time. Here is a part of the stack: at org.eclipse.jdt.core.tests.model.AbstractJavaModelTests.createJavaProject(AbstractJavaModelTests.java:1268) at org.eclipse.jdt.core.tests.model.JavaProjectTests.testPackageFragmentRootNonJavaResources8(JavaProjectTests.java:1557) Hi, I also get this bug in my own junit test, which creates a java project. But my target platform is Eclipse 3.7.2. with 3.7.1. i didn't get this error. java.lang.IllegalArgumentException: Element not found /.org.eclipse.jdt.core.external.folders/.link9. at org.eclipse.core.internal.watson.ElementTree.elementNotFound(ElementTree.java:256) at org.eclipse.core.internal.watson.ElementTree.createElement(ElementTree.java:184) at org.eclipse.core.internal.resources.Workspace.createResource(Workspace.java:1369) at org.eclipse.core.internal.resources.Workspace.createResource(Workspace.java:1322) at org.eclipse.core.internal.localstore.RefreshLocalVisitor.createResource(RefreshLocalVisitor.java:80) at org.eclipse.core.internal.localstore.RefreshLocalAliasVisitor.createResource(RefreshLocalAliasVisitor.java:38) at org.eclipse.core.internal.localstore.RefreshLocalVisitor.synchronizeExistence(RefreshLocalVisitor.java:219) at org.eclipse.core.internal.localstore.RefreshLocalVisitor.visit(RefreshLocalVisitor.java:293) at org.eclipse.core.internal.localstore.UnifiedTree.accept(UnifiedTree.java:110) at org.eclipse.core.internal.localstore.FileSystemResourceManager.refreshResource(FileSystemResourceManager.java:920) at org.eclipse.core.internal.localstore.FileSystemResourceManager.refresh(FileSystemResourceManager.java:904) at org.eclipse.core.internal.resources.Resource.refreshLocal(Resource.java:1663) at org.eclipse.core.internal.resources.Resource.createLink(Resource.java:687) at org.eclipse.core.internal.resources.Resource.createLink(Resource.java:623) at org.eclipse.jdt.internal.core.ExternalFoldersManager.createLinkFolder(ExternalFoldersManager.java:153) at org.eclipse.jdt.internal.core.ExternalFoldersManager.createLinkFolder(ExternalFoldersManager.java:145) at org.eclipse.jdt.internal.core.ExternalFolderChange.updateExternalFoldersIfNecessary(ExternalFolderChange.java:48) at org.eclipse.jdt.internal.core.ChangeClasspathOperation.classpathChanged(ChangeClasspathOperation.java:62) at org.eclipse.jdt.internal.core.SetClasspathOperation.executeOperation(SetClasspathOperation.java:74) at org.eclipse.jdt.internal.core.JavaModelOperation.run(JavaModelOperation.java:728) at org.eclipse.core.internal.resources.Workspace.run(Workspace.java:2344) at org.eclipse.jdt.internal.core.JavaModelOperation.runOperation(JavaModelOperation.java:793) at org.eclipse.jdt.internal.core.JavaProject.setRawClasspath(JavaProject.java:3093) at org.eclipse.jdt.internal.core.JavaProject.setRawClasspath(JavaProject.java:3055) at org.eclipse.jdt.internal.core.JavaProject.setRawClasspath(JavaProject.java:3067) at We got this twice over the past 2 days. Please look into this during M7. Jay, given the number of tests that potentially trigger this bug, what about moving the test harness into the core (e.g., ExternalFoldersManager#createLinkFolder()) guarded by a flag that defaults to false and is set to true from a place like AbstractJavaModelTest? Wouldn't that increase our chance of getting more information? Hopefully, we can remove everything again during M7. Created attachment 212774 [details]
More troubleshooting logs
Thanks, Stephan. I have added some code in the ExternalFoldersManager to log the state in case of an exception. To help us enable this in other environments (like Stefan's, where he recently reported), the flag is in the form of a system property.
Also, I am assuming the Core tests are run before JDT/UI tests. Else, we will have to pass the property via a VM argument.
Stephan, can you look the patch and see if you think any other information such as pendingFolders would help?
I will push this changes to master once M6 is out.
(In reply to comment #14) > Also, I am assuming the Core tests are run before JDT/UI tests. Else, we will > have to pass the property via a VM argument. Tests from different plug-ins are run in separate VMs, so the property will not be passed (test.xml launches the tests). But I just set the property in the UI tests now: http://git.eclipse.org/c/jdt/eclipse.jdt.ui.git/commit/?id=7bbe9b200e2038f2a18dd4bf9b010385f95ab3de (In reply to comment #15) > But I just set the property in the UI tests now: > http://git.eclipse.org/c/jdt/eclipse.jdt.ui.git/commit/?id=7bbe9b200e2038f2a18dd4bf9b010385f95ab3de Thanks, Markus! Now that M6 is out, I have pushed the troubleshooting changes here: http://git.eclipse.org/c/jdt/eclipse.jdt.core.git/commit/?id=e84db8d4c6681c452df342e0bb55c2450eb0a239 (In reply to comment #16) > Now that M6 is out, I have pushed the troubleshooting changes here: > http://git.eclipse.org/c/jdt/eclipse.jdt.core.git/commit/?id=e84db8d4c6681c452df342e0bb55c2450eb0a239 Satyam, given these changes may be left in for a while and we are in M7, let us get it reviewed. Thanks. +1 for the logging code. I'm also seeing that error in my test runs for the STS Gradle tooling. It is causing somewhat 'random' test failures. I have 1 or 2 out of 100 tests failing on a typical test run. They are always different tests failing with a similar stack trace. I think the error has something to do with the fact that the classpath in my projects typically contains a classpath container which in turn resolves to something that contains references to folders (rather than just jar files). (In reply to comment #19) > I'm also seeing that error in my test runs for the STS Gradle tooling. Could you by any chance try with the HEAD version of JDT/Core, if you aren't already doing that and share what you have in your .log file? We have added some trouble-shooting logs in the code that would give us some information on the state when the failure occurs. > I think the error has something to do with the fact that the classpath in my > projects typically contains a classpath container which in turn resolves to > something that contains references to folders (rather than just jar files). That is expected since the external folder manager, which is failing, is meant for folders. Fix for bug 376724 could fix potentially fix this. However, as tests are not running, we will not be able to confirm if this is fixed by M7. Hence, moving to RC1. Unfortunately it is not practical for us to run with JDT head. The reason is that Gradle and Groovy tools are patching JDT core. The patch is for a very specific version of JDT core and needs to be redone for every new version we want to support. We are however rather certain that the bug within the original code, not our patches. I feel like this bug is really very annoying and we sure want to get it fixed and help you as much as possible. I have put together a small eclipse plugin project containing a JUnit plugin test that relatively reliably reproduces the bug when I run it with target platform = Unmodified Eclipse 3.7.2 RCP. From experience seeing the bug, we figured it comes about when this sequence of events happen: - java project created - classpath container with folders (instead of just jars) added - project deleted - project with same name and similar features created It doesn't always happen, but it seems repeating this enough times is almost certain to trigger exception eventually. I have some code that does this kind of thing in a loop. It usually hits the error after about 100 iterations for me. Sometimes sooner (I've seen it once after only 10 iterations). Hopefully this can help you determine the exact cause of the problem and whether or not you have indeed fixed it with https://bugs.eclipse.org/bugs/show_bug.cgi?id=376724 Created attachment 214571 [details]
plugin project containing JUnit plugin test that reproduces the exception
(In reply to comment #23) > Created attachment 214571 [details] > plugin project containing JUnit plugin test that reproduces the exception This is cool, thanks, Kris! Running this test with -Djdt.bug.367669=non-null I see output like this: java.lang.IllegalArgumentException: Element not found: /.org.eclipse.jdt.core.external.folders/.link145. <<Stack trace omitted>> ============================================================================================================ The following logs are created for troubleshooting bug: https://bugs.eclipse.org/bugs/show_bug.cgi?id=367669 Exteral folder: /home/stephan/workspaces/jdt-core-git/bug367669-external-folders/dslSupport Link folder: F/.org.eclipse.jdt.core.external.folders/.link146 External folder exists Link for folder exists External Folder Project exists with following content: <?xml version="1.0" encoding="UTF-8"?> <projectDescription> <name>.org.eclipse.jdt.core.external.folders</name> <comment></comment> <projects> </projects> <buildSpec> </buildSpec> <natures> </natures> <linkedResources> <link> <name>.link146</name> <type>2</type> <location>/home/stephan/workspaces/jdt-core-git/bug367669-external-folders/dslSupport</location> </link> </linkedResources> </projectDescription> ========================================== Debug information ends ========================================== Using "Run" I see the test failing most the time, however, in debug mode I couldn't yet reproduce. Here's the bad news: Kris' test still reproduces the bug when I apply attachment 214487 [details] from Bug 376724 comment 3. But maybe this observation helps: I consistently see that the IAE is reported against .link<n> whereas the debug output shows a linked resource .link<n+1>. (In reply to comment #25) > Here's the bad news: Kris' test still reproduces the bug when I apply > attachment 214487 [details] from Bug 376724 comment 3. correct: from Bug 376724 comment 5. (In reply to comment #25) > But maybe this observation helps: I consistently see that the IAE is reported > against .link<n> whereas the debug output shows a linked resource .link<n+1>. Interesting. Either there is another folder involved while refreshing, which is unlikely or there is a problem while simultaneously accessing "this.counter" I have my questions about the thread safety of the code that post increments 'counter'. However, it's only theoretical assessment and unfortunately I don't have a linux or mac environment to try with. And this doesn't happen with windows.
Stephan, could you try this following code inside ExternalFoldersManageraddFolder()?
do {
String linkName = null;
synchronized (this) {
linkName = LINKED_FOLDER_NAME + this.counter++;
}
result = externalFoldersProject.getFolder(linkName);
} while (result.exists());
Okay, I admit, I don't like the way ExternalFoldersManager looks with so many synchronized methods, blocks and even collections :(
I'm approaching the problem from the opposite direction: with sysout debugging in core.resources code I found this:
RefreshLocalAliasVisitor is creating a resource like so:
- createResource
node = "/.org.eclipse.jdt.core.external.folders/.link76/dsld"
target = "F/.org.eclipse.jdt.core.external.folders/.link76/dsld"
- then the alias manager finds this alias:
"F/.org.eclipse.jdt.core.external.folders/.link75/dsld"
- createResource tries to create the resource for this path
-> fails because the parent handle does not exist: "/.org.eclipse.jdt.core.external.folders/.link75"
Wouldn't that mean that the alias manager is answering outdated aliases?
This is supported by additional sysout in AliasManager.LocationMap.matchingResourcesDo(..):
normally this method isn't even called but directly before the exception I'm seeing plenty of invocations incl. two yielding non-null values:
value=P/.org.eclipse.jdt.core.external.folders
value=[F/.org.eclipse.jdt.core.external.folders/.link75, F/.org.eclipse.jdt.core.external.folders/.link76]
Next I added sysout to AliasManager.hasNoAliases(..) yielding this printout:
- normally 14 hits, all with noAliases==true
- in the exception case:
Creating: 76
no aliases L/bork/.project = true
no aliases P/bork = true
no aliases L/bork/.project = true
no aliases L/bork/.classpath = true
no aliases F/bork/src = true
no aliases L/.org.eclipse.jdt.core.external.folders/.project = true
no aliases P/.org.eclipse.jdt.core.external.folders = true
no aliases L/bork/.classpath = true
no aliases L/.org.eclipse.jdt.core.external.folders/.project = true
no aliases P/.org.eclipse.jdt.core.external.folders = true
Try creating F/.org.eclipse.jdt.core.external.folders/.link76
no aliases L/.org.eclipse.jdt.core.external.folders/.project = false
The "Try creating ..." line is from ExternalFoldersManager.createLinkFolder before calling createLink(..).
After this line hasNoAliases() apparently *should* still answer true but in the buggy case it says false,
and from there on outdated aliases drive us deeper into trouble.
Here's the stack from a bogus call that creates an alias to the external folders project: java.lang.RuntimeException: resource = P/.org.eclipse.jdt.core.external.folders at org.eclipse.core.internal.resources.AliasManager$AddToCollectionDoit.doit(AliasManager.java:60) at org.eclipse.core.internal.resources.AliasManager$LocationMap.overLappingResourcesDo(AliasManager.java:233) at org.eclipse.core.internal.resources.AliasManager.buildAliasedProjectsSet(AliasManager.java:398) at org.eclipse.core.internal.resources.AliasManager.updateStructureChanges(AliasManager.java:772) at org.eclipse.core.internal.resources.AliasManager.hasNoAliases(AliasManager.java:626) at org.eclipse.core.internal.resources.AliasManager.updateAliases(AliasManager.java:723) at org.eclipse.core.internal.localstore.FileSystemResourceManager.internalWrite(FileSystemResourceManager.java:649) at org.eclipse.core.internal.resources.Project.writeDescription(Project.java:1465) at org.eclipse.core.internal.resources.Project.writeDescription(Project.java:1446) at org.eclipse.core.internal.resources.Resource.createLink(Resource.java:696) at org.eclipse.core.internal.resources.Resource.createLink(Resource.java:647) at org.eclipse.jdt.internal.core.ExternalFoldersManager.createLinkFolder(ExternalFoldersManager.java:167) at org.eclipse.jdt.internal.core.ExternalFoldersManager.createLinkFolder(ExternalFoldersManager.java:153) at org.eclipse.jdt.internal.core.ExternalFolderChange.updateExternalFoldersIfNecessary(ExternalFolderChange.java:48) at org.eclipse.jdt.internal.core.ChangeClasspathOperation.classpathChanged(ChangeClasspathOperation.java:62) at org.eclipse.jdt.internal.core.SetClasspathOperation.executeOperation(SetClasspathOperation.java:74) at org.eclipse.jdt.internal.core.JavaModelOperation.run(JavaModelOperation.java:728) at org.eclipse.core.internal.resources.Workspace.run(Workspace.java:2344) at org.eclipse.jdt.internal.core.JavaModelOperation.runOperation(JavaModelOperation.java:793) at org.eclipse.jdt.internal.core.JavaProject.setRawClasspath(JavaProject.java:3095) at org.eclipse.jdt.internal.core.JavaProject.setRawClasspath(JavaProject.java:3057) at org.eclipse.jdt.internal.core.JavaProject.setRawClasspath(JavaProject.java:3110) at com.springsource.sts.gradle.core.dsld.GradleDSLDClasspathContainer.addTo(GradleDSLDClasspathContainer.java:98) at bug367669.external.folders.BugTest.testIt(BugTest.java:53) immediately after this things go havoc: no aliases P/.org.eclipse.jdt.core.external.folders = false AliasManager value=P/.org.eclipse.jdt.core.external.folders etc. like in the previous comment. I assume the external links project should never be aliased? I'm yet to find any impact of concurrency Here's how concurrency plays into the issue: On the main thread SetClasspathOperation is working (see stacks in previous comments). On another thread deletion of the project from the previous test iteration is still working: at org.eclipse.core.internal.resources.ResourceTree.deletedFolder(ResourceTree.java:146) at org.eclipse.core.internal.resources.ResourceTree.internalDeleteFolder(ResourceTree.java:339) at org.eclipse.core.internal.resources.ResourceTree.standardDeleteFolder(ResourceTree.java:798) at org.eclipse.core.internal.resources.Resource.unprotectedDelete(Resource.java:1978) at org.eclipse.core.internal.resources.Resource.delete(Resource.java:804) at org.eclipse.core.internal.resources.Resource.delete(Resource.java:770) at org.eclipse.jdt.internal.core.ExternalFoldersManager.cleanUp(ExternalFoldersManager.java:246) at org.eclipse.jdt.internal.core.JavaModelManager.saving(JavaModelManager.java:4249) at org.eclipse.core.internal.resources.SaveManager.executeLifecycle(SaveManager.java:383) at org.eclipse.core.internal.resources.SaveManager$1.run(SaveManager.java:192) at org.eclipse.core.runtime.SafeRunner.run(SafeRunner.java:42) at org.eclipse.core.internal.resources.SaveManager.broadcastLifecycle(SaveManager.java:195) at org.eclipse.core.internal.resources.SaveManager.save(SaveManager.java:1130) at org.eclipse.core.internal.resources.SaveManager.save(SaveManager.java:1109) at org.eclipse.core.internal.resources.DelayedSnapshotJob.run(DelayedSnapshotJob.java:51) at org.eclipse.core.internal.jobs.Worker.run(Worker.java:54) That's the common part, from where I can see one remove (OK) and one add (NOK): removing F/.org.eclipse.jdt.core.external.folders/.link332 at /home/stephan/workspaces/jdt-core-git/bug367669-external-folders/dslSupport at org.eclipse.core.internal.resources.AliasManager$LocationMap.remove(AliasManager.java:284) at org.eclipse.core.internal.resources.AliasManager.removeFromLocationsMap(AliasManager.java:687) at org.eclipse.core.internal.resources.AliasManager.handleEvent(AliasManager.java:610) at org.eclipse.core.internal.resources.Workspace.broadcastEvent(Workspace.java:390) at org.eclipse.core.internal.resources.Resource.deleteResource(Resource.java:870) at org.eclipse.core.internal.resources.ResourceTree.deletedFolder(ResourceTree.java:146) adding F/.org.eclipse.jdt.core.external.folders/.link332 at /home/stephan/workspaces/jdt-core-git/bug367669-external-folders/dslSupport at org.eclipse.core.internal.resources.AliasManager$LocationMap.add(AliasManager.java:143) at org.eclipse.core.internal.resources.AliasManager.addToLocationsMap(AliasManager.java:397) at org.eclipse.core.internal.resources.AliasManager.updateStructureChanges(AliasManager.java:786) at org.eclipse.core.internal.resources.AliasManager.hasNoAliases(AliasManager.java:645) at org.eclipse.core.internal.resources.AliasManager.updateAliases(AliasManager.java:742) at org.eclipse.core.internal.localstore.FileSystemResourceManager.internalWrite(FileSystemResourceManager.java:649) at org.eclipse.core.internal.resources.Project.writeDescription(Project.java:1465) at org.eclipse.core.internal.resources.Project.writeDescription(Project.java:1446) at org.eclipse.core.internal.resources.Resource.deleteResource(Resource.java:886) at org.eclipse.core.internal.resources.ResourceTree.deletedFolder(ResourceTree.java:146) What's that? We are removing .link332 and while doing so we re-add it again?? The next test iteration creates .link333 to point to the same location which is recognized as a duplicate - hence we start creating bogus aliases. Looks like racing between removing old links and adding new links. I made a quick experiment with protecting methods creadLinkFolder and cleanUp in ExternalFoldersManager with a modifyRule for the project. Unfortunately, even with this protection the bug still occurs. I'm not sure why ExternalFoldersManager is not using scheduling rules. Should we coordinate createLinkFolder and cleanUp using synchronized? Maybe I'm still missing a piece in my analysis, but I think this looks like a promising track. From all my analysis little points towards the ExternalFoldersManager, most is happening inside the AliasManager. Hence I'm moving the bug to platform resources for advice. Let me summarize my findings: We have a loop of creation and deletion of identical projects. During setRawClasspath of project n+1 someone is trying to re-create a linked folder for project n, which has already been deleted. I never succeeded to see the bug in debug mode but it is fairly stable in run mode, thus all the analysis is based on sysout. Here's what a good run does: - delete project n - create project n+1 - before opening project n+1 a DelayedSnapshotJob triggers ExternalFoldersManager.cleanUp which invokes ResourceTree.deleteFolder - during AliasManager.updateStructureChanges we find changedProjects == true and setup a clean new locationsMap - only later when project n+1 sets up its linked folder do we see calls to addToLocationsMap for the new linked folder. Here's what a bad run does: - delete project n - create project n+1 - proceed initializing project n+1 incl. adding JRE to its raw classpath - intermediate steps keep adding the *old* linked folder to the locationsMap (addToLocationsMap) - only then the DelayedSnapshotJob invokes ResourceTree.deleteFolder as mentioned above, but now this goes awry: - in updateStructureChanges() the flag changedProjects is no longer true - we find the old linked folder in changedLinks (because it's being deleted), find it is still [*] isLinked() and thus re-add it to the locationsMap! - when adding the *new* linked folder, an alias for the external folders project is detected - somehow this triggers that a resource for the old link folder is being created, which then throws the IAE because the file system entry has long gone. I don't see any fine grained concurrency but only a question of how the top level actions in the test interleave with the DelayedSnapshotJob. Note that the latter is protected with a workspace rule. Question: - Is it wrong to defer ResourceTree.deleteFolder to the DelayedSnapshotJob? [*] perhaps here's the crux: don't we just find the link *target* existing? Do we prematurely conclude that the resource itself (the link) also exists? Created attachment 214761 [details]
console log of a good test run
Created attachment 214762 [details]
console log of a bad iteration
Created attachment 214763 [details]
AliasManager.java with debug sysouts
Created attachment 214764 [details]
stack traces at some interesting points in time
Created attachment 214765 [details]
test main with debug sysouts
(In reply to comment #37) > Created attachment 214765 [details] > test main with debug sysouts This also contains scheduling of another job which makes the bug a bit more stable on my machine (the more debug output I added, the less frequently the bug occurred). Today while running JDT/Core tests, I saw these in the log file, even though the tests themselves passed. The error looks relevant, even though not same as the ones reported here. !ENTRY org.eclipse.jdt.core 4 4 2012-04-30 19:14:47.691 !MESSAGE Error while creating a link for external folder :C:/work/JDT/externalLib !STACK 1 org.eclipse.core.internal.resources.ResourceException: Cannot create linked resource '/.org.eclipse.jdt.core.external.folders/.link59'. The parent resource is not accessible. at org.eclipse.core.internal.resources.Resource.assertLinkRequirements(Resource.java:181) at org.eclipse.core.internal.resources.Resource.createLink(Resource.java:673) at org.eclipse.core.internal.resources.Resource.createLink(Resource.java:647) at org.eclipse.jdt.internal.core.ExternalFoldersManager.createLinkFolder(ExternalFoldersManager.java:166) at org.eclipse.jdt.internal.core.ExternalFoldersManager.createPendingFolders(ExternalFoldersManager.java:230) at org.eclipse.jdt.core.JavaCore.initializeAfterLoad(JavaCore.java:3944) at org.eclipse.jdt.core.tests.model.ExternalJarDeltaTests.testExternalJarChanged5(ExternalJarDeltaTests.java:262) (In reply to comment #39) > Today while running JDT/Core tests, I saw these in the log file, even though > the tests themselves passed. The error looks relevant, even though not same as > the ones reported here. I'd say its another symptom of the same root cause, probably. Only one thing looks significantly different to me: in that test we have a simulated exit/restart cycle, which means the DelayedSnapshotJob should be gone by then. But from my observations, once we're in the bad state that can be quite sticky. Did you also see any of or debug output? (In reply to comment #40) > Did you also see any of or debug output? No, if you meant 'our', I didn't. Also, On subsequent runs, the error was gone. (In reply to comment #41) > (In reply to comment #40) > > Did you also see any of or debug output? > > No, if you meant 'our', ... sure did, thanks for mind reading :) One more observations: I could only observe the bug when removing the last link to external and thus removing the external folders project itself. Just the presence of another equally shaped project seems to prevent the bug. A possible solution: I could prevent the bug from happening by this change in AliasManager.resourceChanged(..): - if (delta.getAffectedChildren(IResourceDelta.ADDED | IResourceDelta.REMOVED).length > 0) + if (delta.getAffectedChildren(IResourceDelta.ADDED | IResourceDelta.REMOVED, IContainer.INCLUDE_HIDDEN).length > 0) This makes a difference when ExternalFoldersManager#cleanUp() calls project.delete(..) because the external folders project is in fact *hidden*! The change ensures that AliasManager.updateStructureChanges() enters the good branch, where no undead links are resurrected. I don't know for sure, if this fixes the root cause are just masks the problem, but it's the best proposal I have for now. Any comments from platform resources? (In reply to comment #42) > Any comments from platform resources? ping? This bug is causing test failures on a regular basis. We are seeing this problem on our builds as well. It is causing so much havoc that we are considering downgrading our build system to test against 37.0 instead of 3.7.2 or later. I know this bug has gotten a bit long documenting my debugging trail. However, please note that comment 42 has a possible solution! I don't think you really need to read anything prior to comment 32, where my findings up-to that point are summarized. To correlate debugging output with the sources, please refer to comment 37. HTH. I created a feature patch and an update site here: https://bugs.eclipse.org/bugs/show_bug.cgi?id=367669 This works for me locally/ We will be trying this in our builds to make sure it works there as well. This feature patch works against 3.7.2 only. If there is a need, I will create a patch for 4.2 as well, but since 4.2 is a moving target and patches need a precise version range, it will be tricky to get right. (In reply to comment #46) > I created a feature patch and an update site here: > > https://bugs.eclipse.org/bugs/show_bug.cgi?id=367669 > > This works for me locally/ We will be trying this in our builds to make sure > it works there as well. > > This feature patch works against 3.7.2 only. If there is a need, I will create > a patch for 4.2 as well, but since 4.2 is a moving target and patches need a > precise version range, it will be tricky to get right. Hi Andrew, The update site that you have mentioned is this bug url :). Can you please give the correct url? Thanks. > Hi Andrew, > The update site that you have mentioned is this bug url :). Can you please give > the correct url? Thanks. Ha! That was certainly not intentional. Try this: http://dist.springsource.com/release/TOOLS/patches/bug367669 (In reply to comment #46) > This feature patch works against 3.7.2 only. If there is a need, I will create > a patch for 4.2 as well, but since 4.2 is a moving target and patches need a > precise version range, it will be tricky to get right. Andrew, is this just a packaging of Stephan's recommended fix from comment #42? I can't actually see anything at the URL you gave. I just see: <Error><Code>AccessDenied</Code><Message>Access Denied</Message><RequestId>E4596C7A86670BBE</RequestId><HostId>miTIDxQuVyR4DFd/dLVsQ9xjJbPfTnDE2gI1fP/5VdDSnsrHeYu/EKXNtVGYW5Q/</HostId></Error> Yes, this is just a packaging of Stephan's proposed fix. http://dist.springsource.com/release/TOOLS/patches/bug367669/artifacts.jar should work for you. Ping - any chance to address this for RC2? Also, Andrew, if you have been running tests against the patch, could you please report whether it reliably solved the issue / created new issues? Thanks. (In reply to comment #51) > Ping - any chance to address this for RC2? Yes. I'm looking at it for 3.8. Was just distracted by other tasks. Hi Stephan, The feature patch is based off of Eclipse 3.7.2 and so will not install into 3.8 or 4.2. I did run it against Kris's test case, as well as all of Groovy-Eclipse's and SpringSource Tool Suite tests. All are passing. This is of course not definitive, but since this patch is only going into test target platforms, it is sufficient for my purposes. Szymon, thanks for taking a look at this. Stephan, just to double check. I'm looking at the suggestion in comment 42. Is there any other code I should look at? The fix makes sense. Stephan, could you also prepare a JUnit for it? (In reply to comment #54) > Stephan, just to double check. I'm looking at the suggestion in comment 42. Is > there any other code I should look at? That's the only change I proposed and it seems to fix the problem. I didn't fully understand, why one branch in AliasManager.updateStructureChanges() would actually create the bad result, but the proposed change prevents that branch to be executed in this specific situation. You may want to check if there's more lurking here, but JDT/Core tests should be fine with just my simple change. (In reply to comment #55) > The fix makes sense. Stephan, could you also prepare a JUnit for it? Can you use the contributed test from comment 23? +1 for the suggestion in comment 42. I see a fix was already released, but I don't think it is sufficient. There is a second call to getAffectedChildren in this method that I believe should also iterate over hidden resources. The test case would be someone manually adding/removing a link in the project description file of a hidden project. I fixed the other code path in AliasManager#resourceChanged and released. I spent a couple of hours trying to create a regression test with no luck. Kris de Volder's test case didn't reproduce for me, even after increasing to 5000 iterations. My theory is this fix, while valid, is only solving the sporadic test problems through dumb luck. The underlying problem is covered in bug 244315. Refresh did not handle the case where the parent of an alias had not yet been created. This could happen in a hidden project as in this bug, or in a simpler case where there was no resource change event between creation of the overlapping resource and some child of that resource. So, I will take everyone's word for it that it fixes their problem, but I would not be surprised to see it crop up again until the root cause in bug 244315 is fixed. Many thanks Szymon, Szymon and John! (In reply to comment #59) > ... Kris > de Volder's test case didn't reproduce for me, even after increasing to 5000 > iterations. That's weird. So the timing on our machines must be completely different. I saw the bug just about every time within 500 iterations, many times much earlier. I'm confident that it fixes this particular issue, but I share your doubts that this was the whole story. good luck for bug 244315 :) Yes, thanks. This is very helpful for us. Our test runs have had a < 50% success rate because of this problem. The feature patch fixes the problem for 3.7.2 and this will fix the problem on 3.8/4.2. On my first RC2-based build I still see this bug, which made me look at the plugin version in that build: org.eclipse.core.resources_3.8.0.v20120511-1410.jar Looking at the git history it looks like platform resources forgot to contribute to RC2? Integration hasn't been updated for 10 days. (In reply to comment #62) > On my first RC2-based build I still see this bug, which made me look at the > plugin version in that build: > org.eclipse.core.resources_3.8.0.v20120511-1410.jar > Looking at the git history it looks like platform resources forgot to > contribute to RC2? Integration hasn't been updated for 10 days. You're right. This extra manual step is too error prone. I have updated integration. The bug has not occurred in the Object Teams build since adopting the fix. Thanks! (In reply to comment #16) > Now that M6 is out, I have pushed the troubleshooting changes here: > http://git.eclipse.org/c/jdt/eclipse.jdt.core.git/commit/ > ?id=e84db8d4c6681c452df342e0bb55c2450eb0a239 This code is still present in master and we don't need it anymore. I will remove it for M7. (In reply to comment #65) > This code is still present in master and we don't need it anymore. I will > remove it for M7. Done via df26c679ec361eae61785b6b440639645b574764. Are the properties set in two jdt.ui tests still used somewhere?
System.setProperty("jdt.bug.367669", "non-null");
in PlainJarExportTests and FatJarExportTests.
I do not see where they are used. As setting system properties has potential for sideeffects I prefer to remove it in case it is no longer necessary.
|
In the Object Teams tests I'm intermittently seeing the following exception: java.lang.IllegalArgumentException: Element not found: /.org.eclipse.jdt.core.external.folders/.link15. at org.eclipse.core.internal.watson.ElementTree.elementNotFound(ElementTree.java:256) at org.eclipse.core.internal.watson.ElementTree.createElement(ElementTree.java:184) at org.eclipse.core.internal.resources.Workspace.createResource(Workspace.java:1369) at org.eclipse.core.internal.resources.Workspace.createResource(Workspace.java:1322) at org.eclipse.core.internal.localstore.RefreshLocalVisitor.createResource(RefreshLocalVisitor.java:80) at org.eclipse.core.internal.localstore.RefreshLocalAliasVisitor.createResource(RefreshLocalAliasVisitor.java:38) at org.eclipse.core.internal.localstore.RefreshLocalVisitor.synchronizeExistence(RefreshLocalVisitor.java:219) at org.eclipse.core.internal.localstore.RefreshLocalVisitor.visit(RefreshLocalVisitor.java:293) at org.eclipse.core.internal.localstore.UnifiedTree.accept(UnifiedTree.java:110) at org.eclipse.core.internal.localstore.FileSystemResourceManager.refreshResource(FileSystemResourceManager.java:920) at org.eclipse.core.internal.localstore.FileSystemResourceManager.refresh(FileSystemResourceManager.java:904) at org.eclipse.core.internal.resources.Resource.refreshLocal(Resource.java:1694) at org.eclipse.core.internal.resources.Resource.createLink(Resource.java:711) at org.eclipse.core.internal.resources.Resource.createLink(Resource.java:647) at org.eclipse.jdt.internal.core.ExternalFoldersManager.createLinkFolder(ExternalFoldersManager.java:153) at org.eclipse.jdt.internal.core.ExternalFoldersManager.createLinkFolder(ExternalFoldersManager.java:145) at org.eclipse.jdt.internal.core.ExternalFolderChange.updateExternalFoldersIfNecessary(ExternalFolderChange.java:48) at org.eclipse.jdt.internal.core.ChangeClasspathOperation.classpathChanged(ChangeClasspathOperation.java:62) at org.eclipse.jdt.internal.core.SetClasspathOperation.executeOperation(SetClasspathOperation.java:74) at org.eclipse.jdt.internal.core.JavaModelOperation.run(JavaModelOperation.java:728) at org.eclipse.core.internal.resources.Workspace.run(Workspace.java:2344) at org.eclipse.jdt.internal.core.JavaModelOperation.runOperation(JavaModelOperation.java:793) at org.eclipse.jdt.internal.core.JavaProject.setRawClasspath(JavaProject.java:3147) at org.eclipse.jdt.internal.core.JavaProject.setRawClasspath(JavaProject.java:3109) at org.eclipse.jdt.internal.core.JavaProject.setRawClasspath(JavaProject.java:3162) I suspect that the missing linked resource corresponds to a classpath container. The container initializer uses a path obtained using these steps: installDirectory = bundle.getEntry("/") -> yields s.t. like bundleentry://537.fwk23545827/ FileLocator.toFileURL(installDirectory).getPath() -> yields an absolute path into the area at configuration/org.eclipse.osgi/bundles/537/2/.cp/ At a closer look the above scheme is more complicated than needed and I'm hoping to work around the issue by an easier scheme. Still the IAE looks suspicious to me.