Bug 566262 - [search] AIOOBE in DiskIndex.readChunk
Summary: [search] AIOOBE in DiskIndex.readChunk
Status: VERIFIED FIXED
Alias: None
Product: JDT
Classification: Eclipse Project
Component: Core (show other bugs)
Version: 4.15   Edit
Hardware: PC Linux
: P3 normal (vote)
Target Milestone: 4.18 M3   Edit
Assignee: Simeon Andreev CLA
QA Contact:
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2020-08-21 06:56 EDT by Christian Dietrich CLA
Modified: 2020-11-24 03:22 EST (History)
4 users (show)

See Also:


Attachments
Video showing a reproduction of the problem. (4.53 MB, video/mp4)
2020-10-30 12:19 EDT, Simeon Andreev CLA
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Christian Dietrich CLA 2020-08-21 06:56:55 EDT
i am getting this IAOOBE in my Eclipse 2020-06

!ENTRY org.eclipse.jdt.core 4 4 2020-08-21 12:27:30.568
!MESSAGE Background Indexer Crash Recovery
!STACK 0
java.lang.ArrayIndexOutOfBoundsException: Index 2048 out of bounds for length 2048
	at org.eclipse.jdt.internal.core.index.DiskIndex.readChunk(DiskIndex.java:756)
	at org.eclipse.jdt.internal.core.index.DiskIndex.readAllDocumentNames(DiskIndex.java:634)
	at org.eclipse.jdt.internal.core.index.DiskIndex.mergeWith(DiskIndex.java:533)
	at org.eclipse.jdt.internal.core.index.Index.save(Index.java:216)
	at org.eclipse.jdt.internal.core.search.indexing.IndexManager.saveIndex(IndexManager.java:990)
	at org.eclipse.jdt.internal.core.search.indexing.AddJrtToIndex.execute(AddJrtToIndex.java:274)
	at org.eclipse.jdt.internal.core.search.processing.JobManager.run(JobManager.java:401)
	at java.base/java.lang.Thread.run(Thread.java:834)
Comment 1 Andrey Loskutov CLA 2020-08-27 10:47:46 EDT
We also observe sporadic issues with indexer in our tests, where "same" project with few jar dependencies is added & removed for every test.

Stack traces in 4.15 are:

!ENTRY org.eclipse.jdt.core 4 4 2020-08-03 23:00:04.016
!MESSAGE Background Indexer Crash Recovery
!STACK 0
java.lang.StringIndexOutOfBoundsException: String index out of range: 0
	at java.base/java.lang.StringLatin1.charAt(StringLatin1.java:47)
	at java.base/java.lang.String.charAt(String.java:693)
	at org.eclipse.jdt.internal.core.index.DiskIndex.writeAllDocumentNames(DiskIndex.java:1077)
	at org.eclipse.jdt.internal.core.index.DiskIndex.mergeWith(DiskIndex.java:562)
	at org.eclipse.jdt.internal.core.index.Index.save(Index.java:203)
	at org.eclipse.jdt.internal.core.search.indexing.IndexManager.saveIndex(IndexManager.java:990)
	at org.eclipse.jdt.internal.core.search.indexing.AddJarFileToIndex.execute(AddJarFileToIndex.java:267)
	at org.eclipse.jdt.internal.core.search.processing.JobManager.run(JobManager.java:401)
	at java.base/java.lang.Thread.run(Thread.java:834)
!ENTRY org.eclipse.jdt.core 4 4 2020-08-06 07:01:07.526
!MESSAGE Background Indexer Crash Recovery
!STACK 0
java.lang.ArrayIndexOutOfBoundsException: Index 2048 out of bounds for length 2048
	at org.eclipse.jdt.internal.core.index.DiskIndex.readChunk(DiskIndex.java:756)
	at org.eclipse.jdt.internal.core.index.DiskIndex.readAllDocumentNames(DiskIndex.java:634)
	at org.eclipse.jdt.internal.core.index.DiskIndex.mergeWith(DiskIndex.java:533)
	at org.eclipse.jdt.internal.core.index.Index.save(Index.java:203)
	at org.eclipse.jdt.internal.core.search.indexing.IndexManager.saveIndex(IndexManager.java:990)
	at org.eclipse.jdt.internal.core.search.indexing.AddJarFileToIndex.execute(AddJarFileToIndex.java:267)
	at org.eclipse.jdt.internal.core.search.processing.JobManager.run(JobManager.java:401)
	at java.base/java.lang.Thread.run(Thread.java:834)


Our colleague probably identified the root cause:

"
I haven't found what this test does (that others don't) to cause problems for the indexing code but I do reckon that I've found a bug in AddJrtToIndex and AddJarFileToIndex. Both of them call IndexManager.resetIndex but then continue to work on the old version of 'index'. AddJarFileToIndex does at line 216 and AddJrtToIndex at line 260.

I'd been able to regularly repeat the failure in my testing and having used conditional breakpoints to inject calls of 'index = manager.getIndex(index.getIndexLocation());' following the calls to resetIndex I could no longer see the failure. In AddJarFileToIndex I had to check for index being null following the call and bail out if it was.

I don't know what style rules apply here but I would prefer to see resetIndex returning the new index value.
"


The change in question was done for https://bugs.eclipse.org/bugs/show_bug.cgi?id=251504, where original version that switched to the newly created index was removed and replaced with the version that reuses the index object.

So if the code in question works with stale index files, probably related to the new project dependencies for created project, even if they should be identical to the previous. So may be the index is cleaned up for removed project and in parallel same dependencies are added to the index for a new project.

We should check if the patch below makes sense (similar is needed of course for org.eclipse.jdt.internal.core.search.indexing.AddJrtToIndex.execute(IProgressMonitor) too):

diff --git a/org.eclipse.jdt.core/search/org/eclipse/jdt/internal/core/search/indexing/AddJarFileToIndex.java b/org.eclipse.jdt.core/search/org/eclipse/jdt/internal/core/search/indexing/AddJarFileToIndex.java
index ea72272..ac18323 100644
--- a/org.eclipse.jdt.core/search/org/eclipse/jdt/internal/core/search/indexing/AddJarFileToIndex.java
+++ b/org.eclipse.jdt.core/search/org/eclipse/jdt/internal/core/search/indexing/AddJarFileToIndex.java
@@ -218,6 +218,11 @@
 					this.manager.removeIndex(this.containerPath);
 					return false;
 				}
+				IndexLocation location = this.manager.computeIndexLocation(this.containerPath);
+				Index updatedIndex = this.manager.getIndex(location);
+				if (updatedIndex != index) {
+					index = updatedIndex;
+				}
 				index.separator = JAR_SEPARATOR;
 				IPath indexPath = null;
 				IndexLocation indexLocation;

This is a quick & dirty patch, a better version would be probably to change the return value of org.eclipse.jdt.internal.core.search.indexing.IndexManager.resetIndex(IPath) from boolean to the new Index object, and return null if the index reset failed for some reason.
Comment 2 Simeon Andreev CLA 2020-10-29 10:43:05 EDT
In the test environment at Advantest, the OOB seems to be caused by tests not waiting for the indexer to finish before removing a project (that is being indexed). This can result in an index file (for a jar dependency) to "survive" the removal of a project.

The next test will then create the same project, with the same jar dependency. That test will also not wait for indexing before removing the project. Indexing however will find the "old" indexing file and possibly read from it, while the project removal deletes the same index file.

I assume this sequence can cause many types of indexer problems.

For Christians case, I don't know what caused the OOB.
Comment 3 Simeon Andreev CLA 2020-10-30 12:19:49 EDT
Created attachment 284615 [details]
Video showing a reproduction of the problem.

Can be reproduced with some JDT test code and breakpoints/stepping/resuming:

(e.g. add in jdt.core.tests.model, package org.eclipse.jdt.core.tests.nd.indexer)

public class Bug566262Test extends AbstractJavaModelTests {

	public Bug566262Test(String name) {
		super(name);
	}

	public static Test suite() {
		return buildModelTestSuite(Bug566262Test.class);
	}

	/**
	 * Loops project creation and removal, to check if the JDT indexer will run into a {@link ArrayIndexOutOfBoundsException}.
	 */
	public void testBug566262() throws Exception {
	    IWorkspace workspace = ResourcesPlugin.getWorkspace();

		startLogListening();
		try {
			for (int i = 0; i < 2; ++i) {
				String projectName = "Bug566262Test";
				IWorkspaceRunnable create = new IWorkspaceRunnable() {
					public void run(IProgressMonitor monitor) throws CoreException {
						createTestProject(projectName);
					}
				};
				workspace.run(create, new NullProgressMonitor());
				IProject project = workspace.getRoot().getProject(projectName);

				project.refreshLocal(IResource.DEPTH_INFINITE, new NullProgressMonitor());
				project.build(IncrementalProjectBuilder.FULL_BUILD, new NullProgressMonitor());
				Job.getJobManager().join(ResourcesPlugin.FAMILY_AUTO_BUILD, null);

				Thread.sleep(500);
				project.delete(IResource.FORCE, new NullProgressMonitor());

				waitUntilIndexesReady();
			}
			assertLogEquals(""); // expect no logged errors
		} finally {
			stopLogListening();
		}
	}

	IProject createTestProject(String projectName) throws CoreException {
		String outputFolder = "bin";

		IProject project = ResourcesPlugin.getWorkspace().getRoot().getProject(projectName);
		IProjectDescription description = ResourcesPlugin.getWorkspace().newProjectDescription(projectName);
		description.setNatureIds(new String[] { JavaCore.NATURE_ID });
		project.create(description, new NullProgressMonitor());
		project.open(new NullProgressMonitor());

		JavaProject javaProject = (JavaProject) JavaCore.create(project);

		IClasspathAttribute[] attributes = new IClasspathAttribute[] { JavaCore.newClasspathAttribute(IClasspathAttribute.MODULE, "true") };
		IClasspathEntry jrtEntry = JavaCore.newContainerEntry(JavaRuntime.newDefaultJREContainerPath().append(StandardVMType.ID_STANDARD_VM_TYPE).append("JavaSE-11"), null, attributes, true);
		IClasspathEntry sourcesEntry = JavaCore.newSourceEntry(project.getFile("src").getFullPath(), null, null, project.getFile(outputFolder).getFullPath());

		IClasspathEntry[] classpath = { jrtEntry, sourcesEntry };

		javaProject.writeFileEntries(classpath, project.getFullPath().append(outputFolder));
		return project;
	}
}

See attached video "bug566262_reproduction_jdt_test.mp4".

Reproduction steps:

1. Set breakpoints:
        1.1. DiskIndex [line: 624] - readAllDocumentNames() (at line after returning without doing anything)
        1.2. Index [line: 216] - save() (at line merging index)
        1.3. IndexManager [line: 829] - removeIndex(IPath) (at line removing index file)
2. Debug the test (see code above).
3. Observe concurrent suspend at Index.save() and IndexManager.removeIndex(IPath).
        3.1. Do step over for the IndexManager.removeIndex() suspend.
        3.2. Do resume for the Index.save() suspend.
        3.3. Do resume for the IndexManager.removeIndex() suspend.
4. Observe concurrent suspend at DiskIndex.readAllDocumentNames() and IndexManager.removeIndex(IPath).
        4.1. Do step over for the DiskIndex.readAllDocumentNames() suspend, until the line that reads DiskIndex.bufferEnd.
        4.2. Do step over for the IndexManager.removeIndex() suspend.
        4.3. Do step over for the DiskIndex.readAllDocumentNames() suspend, observe DisKIndex.bufferEnd is 2048.
        4.4. Do resume for the IndexManager.removeIndex() suspend.
        4.5. Do resume for the DiskIndex.readAllDocumentNames() suspend.
5. Observe another hit in Index.save(). Resume this.
6. Observe another hit in DiskIndex.readAllDocumentNames(), step through and observe DiskIndex.bufferEnd is -1, after being read from the stream. Resume.
7. Observe the logged exception:
    Exception in thread "Java indexing" java.lang.ArrayIndexOutOfBoundsException: Index 2048 out of bounds for length 2048
    	at org.eclipse.jdt.internal.core.index.DiskIndex.readChunk(DiskIndex.java:756)
    	at org.eclipse.jdt.internal.core.index.DiskIndex.readAllDocumentNames(DiskIndex.java:634)
    	at org.eclipse.jdt.internal.core.index.DiskIndex.mergeWith(DiskIndex.java:533)
    	at org.eclipse.jdt.internal.core.index.Index.save(Index.java:203)
    	at org.eclipse.jdt.internal.core.search.indexing.IndexManager.saveIndex(IndexManager.java:990)
    	at org.eclipse.jdt.internal.core.search.indexing.AddJrtToIndex.execute(AddJrtToIndex.java:274)
    	at org.eclipse.jdt.internal.core.search.processing.JobManager.run(JobManager.java:401)
    	at java.base/java.lang.Thread.run(Thread.java:834)
Comment 4 Eclipse Genie CLA 2020-11-02 04:25:26 EST
New Gerrit change created: https://git.eclipse.org/r/c/jdt/eclipse.jdt.core/+/171608
Comment 5 Andrey Loskutov CLA 2020-11-03 10:56:04 EST
(In reply to Eclipse Genie from comment #4)
> New Gerrit change created:
> https://git.eclipse.org/r/c/jdt/eclipse.jdt.core/+/171608

With this patch I see in debugger that the new IOException is thrown (expected) and handled at:

Daemon Thread [Java indexing] (Suspended (breakpoint at line 829 in IndexManager))	
	owns: IndexManager  (id=920)	
	IndexManager.removeIndex(IPath) line: 829	
	AddJrtToIndex.execute(IProgressMonitor) line: 288	
	IndexManager(JobManager).run() line: 401	
	Thread.run() line: 834	

So now the "containerPath" argument that we give to IndexManager.removeIndex() is  "/usr/lib/jvm/java-11-openjdk-11.0.8.10-0.el7.x86_64/lib/jrt-fs.jar" and the index file for this path *exists* and will be *really* deleted. Not sure that this is expected / right thing here. I assumed patch should handle the case of *already* deleted indexes?
Comment 6 Simeon Andreev CLA 2020-11-03 11:18:06 EST
(In reply to Andrey Loskutov from comment #5)
> So now the "containerPath" argument that we give to
> IndexManager.removeIndex() is 
> "/usr/lib/jvm/java-11-openjdk-11.0.8.10-0.el7.x86_64/lib/jrt-fs.jar" and the
> index file for this path *exists* and will be *really* deleted.

This is not new. Its the same behavior without the patch, if the race condition doesn't cause an exception.

At least in the reproduction case, the index file should not exist at all after the project is deleted the first time. But it can be written after the project removal, due to the race condition. So the next indexing will find the "stale" index file (which should not exist).

> Not sure  that this is expected / right thing here. I assumed patch should handle the
> case of *already* deleted indexes?

The only thing the patch does is prevent an IOOB exception, throwing an IOException instead. Its not expected to have the index file deleted during indexing. I don't know if that can occur with normal Eclipse usage, it can definitely occur in tests that don't wait for the indexing jobs.
Comment 8 Manoj N Palat CLA 2020-11-18 05:42:24 EST
@Simeon: checking whether this fix is complete - if not the target needs to be readjusted.
Comment 9 Simeon Andreev CLA 2020-11-18 06:43:38 EST
The fix should be enough to prevent the exceptions, from my POV this can be closed.
Comment 10 Vikas Chandra CLA 2020-11-24 03:19:06 EST
Simeon/Andrey, can you please verify this fix?
Comment 11 Andrey Loskutov CLA 2020-11-24 03:22:20 EST
(In reply to Vikas Chandra from comment #10)
> Simeon/Andrey, can you please verify this fix?

Our tests in the build farm run with patched platform since two weeks, so far we had no test fails reported with this error. So I assume this is OK to be verified.