Bug 574227 - [test] failing org.eclipse.jdt.apt.tests.TestAll.testSourceGenAfterDirChange
Summary: [test] failing org.eclipse.jdt.apt.tests.TestAll.testSourceGenAfterDirChange
Status: VERIFIED FIXED
Alias: None
Product: JDT
Classification: Eclipse Project
Component: APT (show other bugs)
Version: 4.21   Edit
Hardware: All All
: P3 normal (vote)
Target Milestone: 4.21 M1   Edit
Assignee: Jörg Kubitz CLA
QA Contact:
URL:
Whiteboard:
Keywords:
: 574280 (view as bug list)
Depends on:
Blocks:
 
Reported: 2021-06-16 03:29 EDT by Jörg Kubitz CLA
Modified: 2023-04-11 08:46 EDT (History)
6 users (show)

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Jörg Kubitz CLA 2021-06-16 03:29:52 EDT
Happend two times in a row
for example https://ci.eclipse.org/jdt/job/eclipse.jdt.core-Gerrit/5016/

"java.lang.AssertionError: Should have already removed old folder by now
	at org.eclipse.jdt.apt.tests.FileGenerationTests.testSourceGenAfterDirChange(FileGenerationTests.java:104)"



Can be reproduced locally when setting a breakpoint in GeneratedSourceFolderManager.configure()
at GeneratedSourceFolderManager:152 (the assert that hits).

When resuming after the breakpoint hit the error is shown while running the test without breakpoint does pass. So its a timing issue.
Comment 1 Jörg Kubitz CLA 2021-06-16 03:38:42 EDT
GeneratedSourceFolderManager._generatedSourceFolder is set in thread [Worker-7: Building] while the assert happens asynchronous in the [main] thread

Thread [Worker-7: Building] (Suspended (breakpoint at line 187 in GeneratedSourceFolderManager))	
	owns: GeneratedSourceFolderManager  (id=128)	
	GeneratedSourceFolderManager.ensureFolderExists(IFolder) line: 187	
	GeneratedSourceFolderManager.ensureFolderExists() line: 218	
	GeneratedResourceChangeListener.addGeneratedSrcFolderTo(Set<IProject>, boolean) line: 128	
	GeneratedResourceChangeListener.resourceChanged(IResourceChangeEvent) line: 96	
	DeltaProcessingState$1.run() line: 473	
	SafeRunner.run(ISafeRunnable) line: 45	
	DeltaProcessingState.resourceChanged(IResourceChangeEvent) line: 466	
	NotificationManager$1.run() line: 305	
	SafeRunner.run(ISafeRunnable) line: 45	
	NotificationManager.notify(ResourceChangeListenerList$ListenerEntry[], ResourceChangeEvent, boolean) line: 295	
	NotificationManager.broadcastChanges(ElementTree, ResourceChangeEvent, boolean) line: 158	
	Workspace.broadcastBuildEvent(Object, int, int) line: 367	
	AutoBuildJob.doBuild(IProgressMonitor) line: 150	
	AutoBuildJob.run(IProgressMonitor) line: 244	
	Worker.run() line: 63
Comment 2 Vikas Chandra CLA 2021-06-17 12:46:20 EDT
Changed to normal since this wastes time !
Comment 3 Jörg Kubitz CLA 2021-06-18 01:37:30 EDT
(In reply to Vikas Chandra from comment #2)
> Changed to normal since this wastes time !

I proposed a patch:
https://git.eclipse.org/r/c/jdt/eclipse.jdt.core/+/182042

(I do not know why it is not added to this bug)
Please review with priority as ~ 3/4 builds currently fail because of this bug.
Comment 4 Sarika Sinha CLA 2021-06-18 02:20:46 EDT
*** Bug 574280 has been marked as a duplicate of this bug. ***
Comment 5 Sarika Sinha CLA 2021-06-18 02:22:46 EDT
Thanks Jörg !

This helps. As I was also looking at this yday, will review this ASAP.
Comment 7 Andrey Loskutov CLA 2021-06-18 10:33:57 EDT
(In reply to Eclipse Genie from comment #6)
> Gerrit change https://git.eclipse.org/r/c/jdt/eclipse.jdt.core/+/182042 was
> merged to [master].
> Commit:
> http://git.eclipse.org/c/jdt/eclipse.jdt.core.git/commit/
> ?id=ccabede0b1a9c0c9560a65ec4bbbca83d15bc945

That did not help, see https://ci.eclipse.org/jdt/job/eclipse.jdt.core-Gerrit/5062/testReport/junit/org.eclipse.jdt.apt.tests/TestAll/testGenSrcDir/

java.lang.AssertionError: Should have already removed old folder by now
	at org.eclipse.jdt.apt.tests.PreferencesTests.testGenSrcDir(PreferencesTests.java:247)
Comment 8 Sarika Sinha CLA 2021-06-18 10:41:59 EDT
(In reply to Andrey Loskutov from comment #7)
> (In reply to Eclipse Genie from comment #6)
> > Gerrit change https://git.eclipse.org/r/c/jdt/eclipse.jdt.core/+/182042 was
> > merged to [master].
> > Commit:
> > http://git.eclipse.org/c/jdt/eclipse.jdt.core.git/commit/
> > ?id=ccabede0b1a9c0c9560a65ec4bbbca83d15bc945
> 
> That did not help, see
> https://ci.eclipse.org/jdt/job/eclipse.jdt.core-Gerrit/5062/testReport/junit/
> org.eclipse.jdt.apt.tests/TestAll/testGenSrcDir/
> 
> java.lang.AssertionError: Should have already removed old folder by now
> 	at
> org.eclipse.jdt.apt.tests.PreferencesTests.testGenSrcDir(PreferencesTests.
> java:247)

I think we need to add a wait after trying to remove. 
Just after calling the Job for remove, the action to configure is called which fails.
Comment 9 Jörg Kubitz CLA 2021-06-18 10:56:52 EDT
(In reply to Andrey Loskutov from comment #7)
> That did not help, see

It did help. It's just not the final answer to all flaws.

> org.eclipse.jdt.apt.tests.PreferencesTests.testGenSrcDir(PreferencesTests.
> java:247)

Well that's another test.

(In reply to Sarika Sinha from comment #8)

> I think we need to add a wait after trying to remove. 
> Just after calling the Job for remove, the action to configure is called
> which fails.

Can you please take over that issue? I debugged this a whole day and got tired about it. I made adding/enabling APT atomic, now probably removing/changing needs to be fixed too. Instead of waiting an immediate update of the directories (in  
AptConfig.setGenSrcDir ?) sounds more reliable to me.
Comment 10 Andrey Loskutov CLA 2021-06-18 11:12:53 EDT
(In reply to Jörg Kubitz from comment #9)
> (In reply to Andrey Loskutov from comment #7)
> > That did not help, see
> 
> It did help. It's just not the final answer to all flaws.
> 
> > org.eclipse.jdt.apt.tests.PreferencesTests.testGenSrcDir(PreferencesTests.
> > java:247)
> 
> Well that's another test.

Sorry, just haven't actually read the test name, assumed there is only one bad case in apt tests.

> Can you please take over that issue?

I will try to spend some time here
Comment 11 Jörg Kubitz CLA 2021-06-18 11:32:55 EDT
(In reply to Andrey Loskutov from comment #10)
> I will try to spend some time here

Good luck. But don't spend too much time on this. It's rather the test which is unrealistic. Nobody can enable APT and change its paths within a second. The tests test a lot more functionalities then the UI uses.
Comment 12 Andrey Loskutov CLA 2021-06-18 11:46:13 EDT
(In reply to Jörg Kubitz from comment #11)
> (In reply to Andrey Loskutov from comment #10)
> > I will try to spend some time here
> 
> Good luck. But don't spend too much time on this. It's rather the test which
> is unrealistic. Nobody can enable APT and change its paths within a second.
> The tests test a lot more functionalities then the UI uses.

If I see it right, the problem was related to *unrelated* instances of GeneratedSourceFolderManager created for the AptProject during project *deletion* and kept in the org.eclipse.jdt.apt.core.internal.AptPlugin.PROJECT_MAP. So right after deletion / cleanup, the test that tried next to rename the generated source folder, got the GeneratedSourceFolderManager from previous run where the source folder was already non null.

I will push a patch shortly.
Comment 13 Andrey Loskutov CLA 2021-06-18 12:59:30 EDT
We have a race condition and a stupid code that creates new source folders *again* via ensureFolderExists() in a call from GeneratedResourceChangeListener.resourceChanged(IResourceChangeEvent) *after* the source folder is deleted in the workspace operation via removeFolder().

So the configure() that follows removeFolder() has the race condition with that event handling callback.
Comment 14 Eclipse Genie CLA 2021-06-18 13:33:01 EDT
New Gerrit change created: https://git.eclipse.org/r/c/jdt/eclipse.jdt.core/+/182187
Comment 16 Andrey Loskutov CLA 2021-06-21 12:37:58 EDT
Should be fixed now.
Comment 17 Sarika Sinha CLA 2021-06-23 06:55:30 EDT
https://ci.eclipse.org/jdt/job/eclipse.jdt.core-Gerrit/5129/

3 tests still failing
org.eclipse.jdt.apt.tests.TestAll.testGenSrcDir
org.eclipse.jdt.apt.tests.TestAll.testSourceGenAfterDirChange
org.eclipse.jdt.apt.tests.TestAll.testSourceGenSubDir

java.lang.AssertionError: Should have already removed old folder by now
	at org.eclipse.jdt.apt.tests.PreferencesTests.testGenSrcDir(PreferencesTests.java:247)
Comment 18 Andrey Loskutov CLA 2021-06-23 07:00:44 EDT
(In reply to Sarika Sinha from comment #17)
> https://ci.eclipse.org/jdt/job/eclipse.jdt.core-Gerrit/5129/
> 
> 3 tests still failing
> org.eclipse.jdt.apt.tests.TestAll.testGenSrcDir
> org.eclipse.jdt.apt.tests.TestAll.testSourceGenAfterDirChange
> org.eclipse.jdt.apt.tests.TestAll.testSourceGenSubDir
> 
> java.lang.AssertionError: Should have already removed old folder by now
> 	at
> org.eclipse.jdt.apt.tests.PreferencesTests.testGenSrcDir(PreferencesTests.
> java:247)

The gerrit is based on a very old branch state, without the changes here.
Comment 19 Manoj N Palat CLA 2021-07-07 01:13:04 EDT
(In reply to Sarika Sinha from comment #17)
> https://ci.eclipse.org/jdt/job/eclipse.jdt.core-Gerrit/5129/
> 
> 3 tests still failing

@Sarika: Any failures seen later? I don't see any in the latest tests. Hence moving to verified. Please do reopen/flag a new follow-up bug in case of seeing this again.

Verified with Eclipse. Version: 2021-09 (4.21) Build id: I20210706-1800
Comment 20 Sarika Sinha CLA 2021-07-07 01:15:18 EDT
(In reply to Manoj Palat from comment #19)
> (In reply to Sarika Sinha from comment #17)
> > https://ci.eclipse.org/jdt/job/eclipse.jdt.core-Gerrit/5129/
> > 
> > 3 tests still failing
> 
> @Sarika: Any failures seen later? I don't see any in the latest tests. Hence
> moving to verified. Please do reopen/flag a new follow-up bug in case of
> seeing this again.
> 
> Verified with Eclipse. Version: 2021-09 (4.21) Build id: I20210706-1800

Did not see this failure after rebasing or with any other gerrit recently.
Comment 21 Brad Davis CLA 2021-07-30 17:14:22 EDT
I'm using the JDT via the VSCode Java extension and this fix prevents me from loading a project.  

With the 0.80.0 version of the redhat.java extension, which in turn relies on the 3.7.0.v20210618-1814 version of jdt.apt.core, when I try to load a multi-module maven project it hangs and jstack shows that the Java process has one thread stuck here:  

"Worker-1: Initialize Workspace" #30 prio=5 os_prio=0 cpu=2996.36ms elapsed=39.67s tid=0x00007ff6bc001800 nid=0x5362 in Object.wait()  [0x00007ff71596c000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(java.base@11.0.11/Native Method)
        - waiting on <no object reference available>
        at org.eclipse.core.internal.jobs.JobManager.join(JobManager.java:1020)
        - waiting to re-lock in wait() <0x0000000082f00000> (a java.util.Collections$SynchronizedSet)
        at org.eclipse.jdt.apt.core.internal.generatedfile.GeneratedSourceFolderManager.removeFolder(GeneratedSourceFolderManager.java:508)
        at org.eclipse.jdt.apt.core.internal.generatedfile.GeneratedSourceFolderManager.folderNamePreferenceChanged(GeneratedSourceFolderManager.java:321)
        at org.eclipse.jdt.apt.core.internal.AptProject.preferenceChanged(AptProject.java:81)
        at org.eclipse.jdt.apt.core.util.AptConfig.setString(AptConfig.java:969)
        at org.eclipse.jdt.apt.core.util.AptConfig.setGenSrcDir(AptConfig.java:917)

This is directly inside the code added by https://git.eclipse.org/r/c/jdt/eclipse.jdt.core/+/182187
Comment 22 Andrey Loskutov CLA 2021-07-30 17:18:49 EDT
(In reply to Brad Davis from comment #21)
> I'm using the JDT via the VSCode Java extension and this fix prevents me
> from loading a project.  
> 
> With the 0.80.0 version of the redhat.java extension, which in turn relies
> on the 3.7.0.v20210618-1814 version of jdt.apt.core, when I try to load a
> multi-module maven project it hangs and jstack shows that the Java process
> has one thread stuck here:  

Please create new bug, attach *full* jstack thread dump and provide steps to reproduce.