Bug 578725 - [autobuild] Random startup issues
Summary: [autobuild] Random startup issues
Status: RESOLVED FIXED
Alias: None
Product: Platform
Classification: Eclipse Project
Component: Resources (show other bugs)
Version: 4.23   Edit
Hardware: PC All
: P3 major (vote)
Target Milestone: 4.23 M3   Edit
Assignee: Jörg Kubitz CLA
QA Contact:
URL:
Whiteboard:
Keywords: regression
: 578730 (view as bug list)
Depends on:
Blocks: 578640
  Show dependency tree
 
Reported: 2022-02-14 00:47 EST by Andrey Loskutov CLA
Modified: 2022-02-15 09:47 EST (History)
3 users (show)

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Andrey Loskutov CLA 2022-02-14 00:47:09 EST
Looks like recent autobuild patches broke some contract. 
JDT tests fail randomly, in such cases we see following errors on startup:

https://ci.eclipse.org/jdt/job/eclipse.jdt.core-Gerrit/5905/artifact/org.eclipse.jdt.core.tests.builder/target/work/data/.metadata/.bak_0.log

!ENTRY org.eclipse.core.jobs 4 2 2022-02-14 05:41:04.850
!MESSAGE An internal error occurred during: "Building".
!STACK 0
java.lang.IllegalArgumentException: endRule without matching beginRule: R/
	at org.eclipse.core.runtime.Assert.isLegal(Assert.java:66)
	at org.eclipse.core.internal.jobs.ImplicitJobs.end(ImplicitJobs.java:117)
	at org.eclipse.core.internal.jobs.JobManager.endRule(JobManager.java:726)
	at org.eclipse.core.internal.resources.WorkManager.checkOut(WorkManager.java:170)
	at org.eclipse.core.internal.resources.Workspace.endOperation(Workspace.java:1515)
	at org.eclipse.core.internal.events.AutoBuildJob.doBuild(AutoBuildJob.java:175)
	at org.eclipse.core.internal.events.AutoBuildJob.run(AutoBuildJob.java:254)
	at org.eclipse.core.internal.jobs.Worker.run(Worker.java:63)

!ENTRY org.eclipse.core.resources 4 2 2022-02-14 05:41:05.036
!MESSAGE Problems occurred when invoking code from plug-in: "org.eclipse.core.resources".
!STACK 0
org.eclipse.core.runtime.AssertionFailedException: assertion failed: 
	at org.eclipse.core.runtime.Assert.isTrue(Assert.java:113)
	at org.eclipse.core.runtime.Assert.isTrue(Assert.java:99)
	at org.eclipse.core.internal.watson.ElementTree.openElementData(ElementTree.java:645)
	at org.eclipse.core.internal.resources.Workspace.getResourceInfo(Workspace.java:1756)
	at org.eclipse.core.internal.resources.Resource.getResourceInfo(Resource.java:1177)
	at org.eclipse.core.internal.resources.NatureManager$1.run(NatureManager.java:148)
	at org.eclipse.core.runtime.SafeRunner.run(SafeRunner.java:45)
	at org.eclipse.core.internal.resources.NatureManager.configureNature(NatureManager.java:163)
	at org.eclipse.core.internal.resources.NatureManager.configureNatures(NatureManager.java:209)
	at org.eclipse.core.internal.resources.Project.basicSetDescription(Project.java:106)
	at org.eclipse.core.internal.resources.Project.setDescription(Project.java:1271)
	at org.eclipse.core.internal.resources.Project.setDescription(Project.java:1298)
	at org.eclipse.jdt.core.tests.builder.TestingEnvironment.addBuilderSpecs(TestingEnvironment.java:44)
	at org.eclipse.jdt.core.tests.builder.TestingEnvironment.createProject(TestingEnvironment.java:523)
	at org.eclipse.jdt.core.tests.builder.TestingEnvironment.addProject(TestingEnvironment.java:193)
	at org.eclipse.jdt.core.tests.builder.TestingEnvironment.addProject(TestingEnvironment.java:188)
	at org.eclipse.jdt.core.tests.builder.AbstractMethodTests.test001(AbstractMethodTests.
Comment 1 Andrey Loskutov CLA 2022-02-14 00:52:23 EST
Jörg, could you please investigate? I suspect changes in job cancelation via bug 578578 could be related.
Comment 2 Andrey Loskutov CLA 2022-02-14 01:21:39 EST
Here, another log file, with probably the reason why following jobs see not modifiable tree state (notification manager must successfully complete, see Workspace startup code). 

https://ci.eclipse.org/jdt/job/eclipse.jdt.core-Gerrit/5905/artifact/org.eclipse.jdt.core.tests.compiler/target/work/data/.metadata/.log

!ENTRY org.eclipse.core.jobs 4 2 2022-02-14 05:32:03.276
!MESSAGE An internal error occurred during: "Building".
!STACK 0
java.lang.IllegalArgumentException: endRule without matching beginRule: R/
	at org.eclipse.core.runtime.Assert.isLegal(Assert.java:66)
	at org.eclipse.core.internal.jobs.ImplicitJobs.end(ImplicitJobs.java:117)
	at org.eclipse.core.internal.jobs.JobManager.endRule(JobManager.java:726)
	at org.eclipse.core.internal.resources.WorkManager.checkOut(WorkManager.java:170)
	at org.eclipse.core.internal.resources.Workspace.endOperation(Workspace.java:1515)
	at org.eclipse.core.internal.events.AutoBuildJob.doBuild(AutoBuildJob.java:175)
	at org.eclipse.core.internal.events.AutoBuildJob.run(AutoBuildJob.java:254)
	at org.eclipse.core.internal.jobs.Worker.run(Worker.java:63)

!ENTRY org.eclipse.core.jobs 4 2 2022-02-14 05:32:04.773
!MESSAGE An internal error occurred during: "Updating workspace".
!STACK 0
org.eclipse.core.runtime.AssertionFailedException: assertion failed: Mismatched begin/endOperation
	at org.eclipse.core.runtime.Assert.isTrue(Assert.java:113)
	at org.eclipse.core.internal.resources.Workspace.endOperation(Workspace.java:1492)
	at org.eclipse.core.internal.resources.Workspace.run(Workspace.java:2327)
	at org.eclipse.core.internal.events.NotificationManager$NotifyJob.run(NotificationManager.java:44)
	at org.eclipse.core.internal.jobs.Worker.run(Worker.java:63)
Comment 4 Jörg Kubitz CLA 2022-02-14 02:38:42 EST
(In reply to Andrey Loskutov from comment #1)
> Jörg, could you please investigate? 

i'll take a look. thanks for pointing o that.
Comment 5 Jörg Kubitz CLA 2022-02-14 03:25:10 EST
i can reproduce it when putting a breakpoint at AutoBuildJob.doBuild(IProgressMonitor):150 and then debug org.eclipse.jdt.core.tests.builder.BasicBuildTests as junit plugin test.
once the breakpoint hit, wait a bit and resume => error.
Comment 6 Eclipse Genie CLA 2022-02-14 03:33:03 EST
New Gerrit change created: https://git.eclipse.org/r/c/platform/eclipse.platform.resources/+/190761
Comment 7 Andrey Loskutov CLA 2022-02-14 03:39:40 EST
(In reply to Jörg Kubitz from comment #5)
> i can reproduce it when putting a breakpoint at
> AutoBuildJob.doBuild(IProgressMonitor):150 and then debug
> org.eclipse.jdt.core.tests.builder.BasicBuildTests as junit plugin test.
> once the breakpoint hit, wait a bit and resume => error.

So workspace.prepareOperation() was is never executed because job was interrupted in parallel, we do cancellation on interrupt now and subMonitor.split(1) was throwing OperationCanceledException because we've interrupted & cancelled the job.

So https://git.eclipse.org/r/c/platform/eclipse.platform.resources/+/190567 was it. 

I assume subMonitor.split(1) should be called outside of try block.
Comment 8 Andrey Loskutov CLA 2022-02-14 04:15:07 EST
(In reply to Andrey Loskutov from comment #7)
> I assume subMonitor.split(1) should be called outside of try block.

There were lot of places where the problem may appear in that way after bug 477409 changes in resources framework, which is the actual root cause. They all may cause similar issues / should be fixed.
Comment 9 Eclipse Genie CLA 2022-02-14 04:35:19 EST
New Gerrit change created: https://git.eclipse.org/r/c/platform/eclipse.platform.resources/+/190762
Comment 10 Andrey Loskutov CLA 2022-02-14 05:02:59 EST
Funny enough, the PDE javadoc check job failed also with same issue yesterday:

https://download.eclipse.org/eclipse/downloads/drops4/I20220213-1800/compilelogs/pde.doc.user.schema.txt

[pde.convertSchemaToHTML] !SESSION 2022-02-13 23:45:07.976 -----------------------------------------------
[pde.convertSchemaToHTML] eclipse.buildId=unknown
[pde.convertSchemaToHTML] java.version=11.0.2
[pde.convertSchemaToHTML] java.vendor=Oracle Corporation
[pde.convertSchemaToHTML] BootLoader constants: OS=linux, ARCH=x86_64, WS=gtk, NL=en_US
[pde.convertSchemaToHTML] Framework arguments:  -application org.eclipse.ant.core.antRunner -quiet -buildfile buildDoc.xml -Dbasedir.properties=cbi_basedirs.properties -Declipse.javadoc=/opt/tools/java/openjdk/jdk-11/latest/bin/javadoc
[pde.convertSchemaToHTML] Command-line arguments:  -data /home/jenkins/agent/workspace/I-build-4.23-github/eclipse.platform.releng.aggregator/eclipse.platform.releng.aggregator/cje-production/gitCache/eclipse.platform.releng.aggregator/eclipse.platform.common/bundles/org.eclipse.pde.doc.user/target/eclipserun-work/data -consolelog -debug -data target/workspace -application org.eclipse.ant.core.antRunner -quiet -buildfile buildDoc.xml -Dbasedir.properties=cbi_basedirs.properties -Declipse.javadoc=/opt/tools/java/openjdk/jdk-11/latest/bin/javadoc
[pde.convertSchemaToHTML] 
[pde.convertSchemaToHTML] !ENTRY org.eclipse.core.jobs 4 2 2022-02-13 23:45:10.149
[pde.convertSchemaToHTML] !MESSAGE An internal error occurred during: "Building".
[pde.convertSchemaToHTML] !STACK 0
[pde.convertSchemaToHTML] java.lang.IllegalArgumentException: endRule without matching beginRule: R/
[pde.convertSchemaToHTML] 	at org.eclipse.core.runtime.Assert.isLegal(Assert.java:66)
[pde.convertSchemaToHTML] 	at org.eclipse.core.internal.jobs.ImplicitJobs.end(ImplicitJobs.java:117)
[pde.convertSchemaToHTML] 	at org.eclipse.core.internal.jobs.JobManager.endRule(JobManager.java:726)
[pde.convertSchemaToHTML] 	at org.eclipse.core.internal.resources.WorkManager.checkOut(WorkManager.java:170)
[pde.convertSchemaToHTML] 	at org.eclipse.core.internal.resources.Workspace.endOperation(Workspace.java:1515)
[pde.convertSchemaToHTML] 	at org.eclipse.core.internal.events.AutoBuildJob.doBuild(AutoBuildJob.java:175)
[pde.convertSchemaToHTML] 	at org.eclipse.core.internal.events.AutoBuildJob.run(AutoBuildJob.java:254)
[pde.convertSchemaToHTML] 	at org.eclipse.core.internal.jobs.Worker.run(Worker.java:63)
Comment 13 Andrey Loskutov CLA 2022-02-14 05:20:13 EST
There were some thousands of resource related test fails in jdt.ui.tests and jdt.ui.tests.refactoring in https://download.eclipse.org/eclipse/downloads/drops4/I20220213-1800/testResults.php. I assume same root cause, but could be other issue too. Will see in the next build if they reappear or not.
Comment 14 Andrey Loskutov CLA 2022-02-14 12:19:05 EST
*** Bug 578730 has been marked as a duplicate of this bug. ***
Comment 15 Andrey Loskutov CLA 2022-02-15 09:47:40 EST
Let assume it is fixed now.