Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

AliasManager not thread-safe (causes random failing org.eclipse.core.tests.internal.alias.BasicAliasTest.testBug256837 ) #95

Open
jukzi opened this issue Apr 29, 2022 · 18 comments
Labels
bug Something isn't working

Comments

@jukzi
Copy link
Contributor

jukzi commented Apr 29, 2022

https://download.eclipse.org/eclipse/downloads/drops4/I20220428-1800/testresults/html/org.eclipse.core.tests.resources_ep424I-unit-win32-java11_win32.win32.x86_64_11.html

java.lang.NullPointerException
at org.eclipse.core.tests.internal.alias.BasicAliasTest.testBug256837(BasicAliasTest.java:457)
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 junit.framework.TestCase.runTest(TestCase.java:177)
at junit.framework.TestCase.runBare(TestCase.java:142)
at junit.framework.TestResult$1.protect(TestResult.java:122)
at junit.framework.TestResult.runProtected(TestResult.java:142)
at junit.framework.TestResult.run(TestResult.java:125)
at junit.framework.TestCase.run(TestCase.java:130)
at junit.framework.TestSuite.runTest(TestSuite.java:241)
at junit.framework.TestSuite.run(TestSuite.java:236)
at org.junit.internal.runners.JUnit38ClassRunner.run(JUnit38ClassRunner.java:90)
at org.junit.runners.Suite.runChild(Suite.java:128)
at org.junit.runners.Suite.runChild(Suite.java:27)
at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
at org.junit.runners.Suite.runChild(Suite.java:128)
at org.junit.runners.Suite.runChild(Suite.java:27)
at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
at org.junit.vintage.engine.execution.RunnerExecutor.execute(RunnerExecutor.java:42)
at org.junit.vintage.engine.VintageTestEngine.executeAllChildren(VintageTestEngine.java:80)
at org.junit.vintage.engine.VintageTestEngine.execute(VintageTestEngine.java:72)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:107)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:88)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:54)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:67)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:52)
at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:114)
at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:86)
at org.junit.platform.launcher.core.DefaultLauncherSession$DelegatingLauncher.execute(DefaultLauncherSession.java:86)
at org.junit.platform.launcher.core.SessionPerRequestLauncher.execute(SessionPerRequestLauncher.java:53)
at org.eclipse.test.EclipseTestRunner.runTests(EclipseTestRunner.java:226)
at org.eclipse.test.EclipseTestRunner.run(EclipseTestRunner.java:202)
at org.eclipse.test.CoreTestApplication.runTests(CoreTestApplication.java:52)
at org.eclipse.test.CoreTestApplication.run(CoreTestApplication.java:35)
at org.eclipse.test.CoreTestApplication.start(CoreTestApplication.java:43)
at org.eclipse.equinox.internal.app.EclipseAppHandle.run(EclipseAppHandle.java:203)
at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.runApplication(EclipseAppLauncher.java:136)
at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.start(EclipseAppLauncher.java:104)
at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:402)
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:659)
at org.eclipse.equinox.launcher.Main.basicRun(Main.java:596)
at org.eclipse.equinox.launcher.Main.run(Main.java:1467)
at org.eclipse.equinox.launcher.Main.main(Main.java:1440)
at org.eclipse.core.launcher.Main.main(Main.java:44)
@laeubi laeubi transferred this issue from eclipse-platform/eclipse.platform.resources Aug 13, 2022
@jukzi
Copy link
Contributor Author

jukzi commented Aug 30, 2022

can be locally reproduced with

Thread.sleep(200)
at org.eclipse.core.internal.resources.ResourceException.provideStackTrace(String, Throwable)

@jukzi
Copy link
Contributor Author

jukzi commented Aug 30, 2022

It is some multi threading problem: if the whole VM is suspended at org.eclipse.core.internal.resources.ResourceTree.standardMoveProject(IProject, IProjectDescription, int, IProgressMonitor)
and only main thread is resumed, then the test passes.
if otherwise only the main thread is suspended there then the test fails.

jukzi pushed a commit to jukzi/eclipse.platform that referenced this issue Aug 31, 2022
@jukzi jukzi linked a pull request Aug 31, 2022 that will close this issue
@mickaelistria
Copy link
Contributor

Looking at the proposed patch, it's unclear to me whether the issue is the test, or the aliasManager that doesn't work as expected... Has this test always been failing (even several years ago), or did it start failing recently because of some side-effect of another change (ie this would be a regression)?

@jukzi
Copy link
Contributor Author

jukzi commented Aug 31, 2022

I don't know how long it failed. It might only became obvious as hardware or software became faster or slower.

@mickaelistria
Copy link
Contributor

So indeed, there is a RefreshJob running at some point in another thread, and the success or failure depends on whether this job has completed before next instruction.
Here is the stack that triggers the RefreshJob (from main thread)

Thread [main] (Suspended (entry into method refresh in RefreshJob))	
	owns: RunnableLock  (id=115)	
	RefreshJob.refresh(IResource) line: 199	
	RefreshManager.refresh(IResource) line: 98	
	FileSystemResourceManager.asyncRefresh(IResource) line: 148	
	FileSystemResourceManager.read(IFile, boolean, IProgressMonitor) line: 833	
	File.getContents(boolean) line: 277	
	File.getContents() line: 268	
	File.getLineSeparator(boolean) line: 448	
	FileSystemResourceManager.internalWrite(IProject, IProjectDescription, int, boolean, boolean) line: 640	
	Project.writeDescription(IProjectDescription, int, boolean, boolean) line: 1421	
	Project.writeDescription(int) line: 1402	
	ResourceTree.movedProjectSubtree(IProject, IProjectDescription) line: 718	
	ResourceTree.standardMoveProject(IProject, IProjectDescription, int, IProgressMonitor) line: 1108	
	Project.move(IProjectDescription, int, IProgressMonitor) line: 993	
	BasicAliasTest.replaceProject(IProject, URI) line: 304	
	BasicAliasTest.testBug256837() line: 411	
[...]

In an ideal world, the "move" opreation wouldn't require to refresh the content, as we do already have some pointers to this content. It would be great to investigate that particular case: if we can get rid of the need to refresh() then it would fix this tests (and maybe other that are of the same kind).

@jukzi
Copy link
Contributor Author

jukzi commented Aug 31, 2022

So moving the project does currently not move the .project file but write the .project with the lineseperator configured in the .project file - which does not exist yet. So the configured lineseperator may even be wrong/forgotten? it should be remembered in memory (or binary move the file instead) -> no File.getLineSeparator necessary -> no error -> no refresh -> no fail

@mickaelistria
Copy link
Contributor

It's only in this particular cases (with links and different FileStore I believe) that the failure happens. The issue is not really about reading the lineSeparator, after all it's OK to try to read a line separator and to try to refresh asynchronously some content on access.
I see 2 possible issues:

  • First, the descriptionFile is considered as exists() but not as isSynchronized(). If we could have the file synchronized at this stage, then there wouldn't be issue with async refresh.
  • Second, and maybe more on the point, is that although a project is created, it seems like the move() operation doesn't send a notification here. Just like creating a new project, I think it's OK to expect a synchronous POST_CHANGE notification. Then the AliasManager would update without need to wait for a separate refresh job to complete.

it should be remembered in memory (or binary move the file instead) -> no File.getLineSeparator necessary -> no error -> no refresh -> no fail

I think it's more the other way round, if there is no refresh, then the test fails (because there was no POST_CHANGE notification.

@mickaelistria
Copy link
Contributor

Actually, I'm wrong and you're right: the POST_CHANGE is sent (good), AliasManager is updated (good), but then the RefreshJob triggers (because of lineSeparator and ResourcesPlugin.PREF_LIGHTWEIGHT_AUTO_REFRESH set to true), so the data from AliasManager is temporarily incorrect at the time test asks for it.
What about setting ResourcesPlugin.PREF_LIGHTWEIGHT_AUTO_REFRESH to false for that test then, so we disable the RefreshJob and have good control over the flow?

@jukzi
Copy link
Contributor Author

jukzi commented Sep 1, 2022

What about setting ResourcesPlugin.PREF_LIGHTWEIGHT_AUTO_REFRESH to false for that test then, so we disable the RefreshJob and have good control over the flow?

+1 if that makes the test fail reproducible
BTW how to move a project with the UI? is that even a possible usecase?

@laeubi
Copy link
Contributor

laeubi commented Sep 1, 2022

how to move a project with the UI?

Goto Package Explorer > Rightclick > Refactor > Move

akurtakov pushed a commit to jukzi/eclipse.platform that referenced this issue Sep 4, 2022
akurtakov pushed a commit to jukzi/eclipse.platform that referenced this issue Sep 4, 2022
@mickaelistria mickaelistria changed the title random failing org.eclipse.core.tests.internal.alias.BasicAliasTest.testBug256837 AliasManager not thread-safe (causes random failing org.eclipse.core.tests.internal.alias.BasicAliasTest.testBug256837 ) Sep 5, 2022
@mickaelistria mickaelistria added the bug Something isn't working label Sep 5, 2022
@jukzi
Copy link
Contributor Author

jukzi commented Sep 5, 2022

What about setting ResourcesPlugin.PREF_LIGHTWEIGHT_AUTO_REFRESH to false for that test then, so we disable the RefreshJob and have good control over the flow?

+1 if that makes the test fail reproducible BTW how to move a project with the UI? is that even a possible usecase?

InstanceScope.INSTANCE.getNode(ResourcesPlugin.PI_RESOURCES)
.putBoolean(ResourcesPlugin.PREF_LIGHTWEIGHT_AUTO_REFRESH, false);

does not make the test fail :-(

@mickaelistria
Copy link
Contributor

I suggest #156 which I hope can improve this in general without need to tweak test.

@mickaelistria
Copy link
Contributor

The patch did suffice for 25 days; that's a relative success! I'll try to look at further issues later.

@jukzi
Copy link
Contributor Author

jukzi commented Jun 13, 2023

recent fail:

Cannot read the array length because "resources" is null
java.lang.NullPointerException: Cannot read the array length because "resources" is null
	at org.eclipse.core.tests.internal.alias.BasicAliasTest.testBug256837(BasicAliasTest.java:431)

@jukzi
Copy link
Contributor Author

jukzi commented Jun 27, 2024

https://download.eclipse.org/eclipse/downloads/drops4/I20240626-1800/testresults/html/org.eclipse.core.tests.resources_ep433I-unit-win32-java17_win32.win32.x86_64_17.html

java.lang.AssertionError:
Expecting actual not to be null
at org.eclipse.core.tests.internal.alias.BasicAliasTest.testBug256837(BasicAliasTest.java:438)
at java.base/java.lang.reflect.Method.invoke(Method.java:568)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants