Bug 423416 - "Index out of bounds" exceptions in CodeCompletionTest
Summary: "Index out of bounds" exceptions in CodeCompletionTest
Status: CLOSED WONTFIX
Alias: None
Product: JDT
Classification: Eclipse Project
Component: Text (show other bugs)
Version: 4.4   Edit
Hardware: All All
: P3 normal (vote)
Target Milestone: ---   Edit
Assignee: JDT-Text-Inbox CLA
QA Contact:
URL:
Whiteboard: stalebug
Keywords: test
: 421699 (view as bug list)
Depends on:
Blocks:
 
Reported: 2013-12-06 06:12 EST by Markus Keller CLA
Modified: 2020-04-17 13:27 EDT (History)
7 users (show)

See Also:


Attachments
JdtTextTestSuite.txt from I20140115-1300 (26.97 KB, text/plain)
2014-01-17 16:23 EST, Markus Keller CLA
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Markus Keller CLA 2013-12-06 06:12:06 EST
(This is bug 421699 in readable form)

M20131113-0800 and N20131205-2000.

Many (12-13) "Index out of bounds" exceptions in CodeCompletionTest like this:

Java Model Exception: Java Model Status [Index out of bounds]
at org.eclipse.jdt.internal.core.Openable.codeComplete(Openable.java:121)
at org.eclipse.jdt.internal.core.CompilationUnit.codeComplete(CompilationUnit.java:358)
at org.eclipse.jdt.internal.core.CompilationUnit.codeComplete(CompilationUnit.java:346)
at org.eclipse.jdt.text.tests.contentassist.CodeCompletionTest.codeComplete(CodeCompletionTest.java:91)
at org.eclipse.jdt.text.tests.contentassist.CodeCompletionTest.testAnonymousTypeCompletion3(CodeCompletionTest.java:272)
at org.eclipse.test.EclipseTestRunner.run(EclipseTestRunner.java:657)
at org.eclipse.test.EclipseTestRunner.run(EclipseTestRunner.java:310)
at org.eclipse.test.UITestApplication$2.run(UITestApplication.java:197)
at org.eclipse.swt.widgets.RunnableLock.run(RunnableLock.java:35)
at org.eclipse.swt.widgets.Synchronizer.runAsyncMessages(Synchronizer.java:136)
at org.eclipse.swt.widgets.Display.runAsyncMessages(Display.java:4145)
at org.eclipse.swt.widgets.Display.readAndDispatch(Display.java:3762)
at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine$9.run(PartRenderingEngine.java:1119)
at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:332)
at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.run(PartRenderingEngine.java:1003)
at org.eclipse.e4.ui.internal.workbench.E4Workbench.createAndRunUI(E4Workbench.java:146)
at org.eclipse.ui.internal.Workbench$5.run(Workbench.java:609)
at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:332)
at org.eclipse.ui.internal.Workbench.createAndRunWorkbench(Workbench.java:563)
at org.eclipse.ui.PlatformUI.createAndRunWorkbench(PlatformUI.java:150)
at org.eclipse.ui.internal.ide.application.IDEApplication.start(IDEApplication.java:125)
at org.eclipse.test.UITestApplication.runApplication(UITestApplication.java:140)
at org.eclipse.test.UITestApplication.run(UITestApplication.java:62)
at org.eclipse.test.UITestApplication.start(UITestApplication.java:212)
at org.eclipse.equinox.internal.app.EclipseAppHandle.run(EclipseAppHandle.java:196)
at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.runApplication(EclipseAppLauncher.java:109)
at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.start(EclipseAppLauncher.java:80)
at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:372)
at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:226)
at org.eclipse.equinox.launcher.Main.invokeFramework(Main.java:636)
at org.eclipse.equinox.launcher.Main.basicRun(Main.java:591)
at org.eclipse.equinox.launcher.Main.run(Main.java:1450)
at org.eclipse.equinox.launcher.Main.main(Main.java:1426)
at org.eclipse.core.launcher.Main.main(Main.java:34)
Comment 1 Markus Keller CLA 2013-12-06 06:14:01 EST
*** Bug 421699 has been marked as a duplicate of this bug. ***
Comment 3 Markus Keller CLA 2013-12-11 08:58:44 EST
Also happened on GTK. Log output from http://download.eclipse.org/eclipse/downloads/drops4/I20131210-2000/testresults/linux.gtk.x86_6.0/org.eclipse.jdt.text.tests.JdtTextTestSuite.txt :

org.eclipse.jdt.text.tests.contentassist.CodeCompletionTest#testAnonymousTypeCompletion3 failed: Index out of bounds
offset: 136
cu: [Working copy] A.java [in test1 [in src [in TestProject1]]]
  package test1
  class A
    void foo()
buffer: org.eclipse.jdt.internal.ui.javaeditor.DocumentAdapter@3ad9531b
source: |package test1;
public class A {
    public void foo() {
        Runnable run= new Runnable();
    }
}
|

=> The exception happens because the CU source is wrong. It's the source from the previous test testAnonymousTypeCompletion2(), which created the same CU.

Added the actual file contents to the log: http://git.eclipse.org/c/jdt/eclipse.jdt.ui.git/commit/?id=3b389e6b5a3a09b4d9e302c053aab4610086c8b2
Comment 4 Dani Megert CLA 2013-12-18 04:53:53 EST
(In reply to Markus Keller from comment #3)
> => The exception happens because the CU source is wrong. It's the source
> from the previous test testAnonymousTypeCompletion2(), which created the
> same CU.

Deletion of the project seems to works since we create the CU with force=false and it would cause a JME if the old CU would still exist. Also, the file creation happens without using file buffers. So, either the file buffer, the JDT Core BufferManager or the code assist infrastructure still has the old source, but it doesn't necessarily cause an exception (#testAnonymousTypeCompletion6):


expected:<package test1; [import java.io.Serializable; //BUG public class A { public void foo() { Serializable run= new Serializable() { };] } } > but was:<package test1; [ import java.util.Locale; import java.io.Serializable; //BUG public class A { public void foo() { Serializable run= new SerializabLocale] } } >

junit.framework.ComparisonFailure: expected:<package test1;
[import java.io.Serializable;
//BUG
public class A {
public void foo() {
Serializable run= new Serializable() {
};]
}
}
> but was:<package test1;
[
import java.util.Locale;

import java.io.Serializable;
//BUG
public class A {
public void foo() {
Serializable run= new SerializabLocale]
}
}
>
Comment 6 Dani Megert CLA 2014-01-06 07:01:27 EST
Enabled logging for all CodeCompletionTests:

http://git.eclipse.org/c/jdt/eclipse.jdt.ui.git/commit/?id=75539f3ab0e73a2b15f1fc62429d01cf2819baa7
Comment 7 Markus Keller CLA 2014-01-17 16:23:35 EST
Created attachment 239112 [details]
JdtTextTestSuite.txt from I20140115-1300

In I20140115-1300, the first failing test was testSetterCompletion1.

File contents were correct, but the buffer contained the source from the last test that used cu test1.A (testAnonymousTypeCompletion6), but using a different DocumentAdapter instance (i.e. a different IWorkingCopy).
Comment 8 Markus Keller CLA 2014-11-13 11:31:27 EST
Very likely a duplicate of bug 436581, see bug 436581 comment 3.
Comment 9 Stephan Herrmann CLA 2015-03-15 16:03:19 EDT
I might be seeing this in https://hudson.eclipse.org/platform/job/eclipse.jdt.ui-Gerrit/162/#showFailuresLink
Next build succeeded with the some input.

The build may soon be removed from hudson so below you find the initial failure.

After that more tests failed with "Wrong number of proposals".



org.eclipse.jdt.text.tests.contentassist.CodeCompletionTest.testAnonymousTypeCompletion4 (from org.eclipse.jdt.text.tests.JdtTextTestSuite)
Failing for the past 1 build (Since Failed#162 )
Took 0.54 sec.
Error Message

Index out of bounds

Stacktrace

org.eclipse.jdt.core.JavaModelException: Index out of bounds
	at org.eclipse.jdt.internal.core.Openable.codeComplete(Openable.java:121)
	at org.eclipse.jdt.internal.core.CompilationUnit.codeComplete(CompilationUnit.java:357)
	at org.eclipse.jdt.internal.core.CompilationUnit.codeComplete(CompilationUnit.java:345)
	at org.eclipse.jdt.text.tests.contentassist.CodeCompletionTest.codeComplete(CodeCompletionTest.java:150)
	at org.eclipse.jdt.text.tests.contentassist.CodeCompletionTest.testAnonymousTypeCompletion4(CodeCompletionTest.java:385)

Standard Output

---- org.eclipse.jdt.text.tests.contentassist.CodeCompletionTest#testAnonymousTypeCompletion4 ----
offset: 160
cu: [Working copy] A.java [in test1 [in src [in TestProject1]]]
  package test1
  class A
    interface Inner
      void doIt()
    void foo()
buffer: org.eclipse.jdt.internal.ui.javaeditor.DocumentAdapter@3bf7a560
source: |package test1;
public class A {
    interface Inner {
        void doIt();
    }
    public void foo() {
        Inner inner= new Inner();
    }
}
|
file contents: |package test1;
public class A {
    public void foo() {
        abstract class Local {
            abstract void doIt();
        }
        Local loc= new Local();
    }
}
|

TestProject1
  /jobs/genie.platform/eclipse.jdt.ui-Gerrit/workspace/org.eclipse.jdt.text.tests/target/work/plugins/org.eclipse.jdt.ui.tests_3.10.100.v20150312-1744/testresources/rtstubs15.jar (not open)
  src
    <default> (not open)
    test1 (not open)
<default> [in src [in TestProject1]]
test1 [in src [in TestProject1]]
  [Working copy] A.java
    package test1
    class A
      interface Inner
        void doIt()
      void foo()
Comment 10 Markus Keller CLA 2015-05-06 12:14:05 EDT
Unfortunately, it looks like bug 436581 comment 4 only reduced the frequency of test failures in CodeCompletionTest, but didn't actually solve the problem.

Somehow, the CU's buffers end up with wrong content, but I have not been able to reproduce this reliably nor to find the actual cause.
Comment 11 Timo Kinnunen CLA 2015-10-25 07:04:15 EDT
Theory:

The file has just been created. Thread A opens the file and starts reading the CU. Meanwhile...
Thread B deletes the file. On Linux and MacOS this succeeds and unlinks the file, but crucially the file won't actually be deleted until thread A closes the file. 
Thread B recreates the file. Due to timing and rounding the new file ends up having the same timestamp as the old file.
Thread A finishes reading the old file. The file is deleted for real sometime later, silently.
Thread A checks that the file exists and on seeing that it does, is left thinking the data it read is what's on the disk.

Thread A could try inspecting more of the file's metadata but the only 100% reliable of detecting this situation is to compare the contents, which requires reading the file. But this is what thread A was trying to do in the first place :(
Comment 12 Stephan Herrmann CLA 2015-10-25 07:13:59 EDT
Timo, your theory sounds convincing. The weakest point, IMHO, is this:

(In reply to Timo Kinnunen from comment #11)
> Due to timing and rounding the new file ends up
> having the same timestamp as the old file.

Is this possible? Is timestamping too coarse grained to distinguish two separate creations of a file with the same path? Do we have sufficient knowledge about those OSes and their filesystem?

Also: what about the failure on win32 reported in comment 5?
Comment 13 Timo Kinnunen CLA 2015-10-25 11:01:43 EDT
(In reply to comment #12)
> Is this possible? Is timestamping too coarse grained to distinguish two separate
> creations of a file with the same path? Do we have sufficient knowledge about
> those OSes and their filesystem?

I tried to look this up earlier and the best I can say is it depends on the filesystem in use. I know ext3 has 1 second resolution (as in seconds from epoch). ext4 can provide nanosecond resolution, but it also allows ext3 filesystems to be mounted as ext4 for backwards-compatibility. So what the resolution might be in practice I don't know. 

> Also: what about the failure on win32 reported in comment 5?

Windows provides a feature called "tunneling" where if a file is deleted and then recreated right afterwards the API restores the old file's creation time on the new file to make it seem like the old file was never deleted at all. According to https://support.microsoft.com/en-us/kb/172190 the rename and delete operations which can trigger this can happen 15 seconds apart or even more.

On Windows the sequence would then be: thread A reads and closes the file, then thread B deletes and recreates the file, then thread A checks if the file still exists.
Comment 14 Markus Keller CLA 2016-04-28 14:42:40 EDT
CodeCompletionTest18.testOverride13 failed for the same reason in I20160427-2000 on Windows.
Comment 15 Bhargavi Mullapudi CLA 2016-08-11 01:47:28 EDT
Issue is seen with IBM SDK with the below version

Version:"1.8.0"
Java(TM) SE Runtime Environment (build pwi3280sr4-20160809_01(SR4))
IBM J9 VM (build 2.8, JRE 1.8.0 Windows Server 2012 R2 x86-32 20160804_313926 (JIT enabled, AOT enabled)
J9VM - R28_20160804_0200_B313926
JIT  - tr.r14.java.green_20160726_121883
GC   - R28_20160804_0200_B313926
J9CL - 20160804_313926)
JCL - 20160701_01 based on Oracle jdk8u101-b13
Comment 16 Noopur Gupta CLA 2017-01-27 01:38:27 EST
These test failures can be seen again in I20170126-1030 on Windows:
- testOverrideCompletion7_bug355926
- testOverrideCompletion8_bug355926
- testOverrideCompletion9_bug355926
- testSetterCompletion1
Comment 17 Eclipse Genie CLA 2020-04-17 13:27:34 EDT
This bug hasn't had any activity in quite some time. Maybe the problem got resolved, was a duplicate of something else, or became less pressing for some reason - or maybe it's still relevant but just hasn't been looked at yet. As such, we're closing this bug.

If you have further information on the current state of the bug, please add it and reopen this bug. The information can be, for example, that the problem still occurs, that you still want the feature, that more information is needed, or that the bug is (for whatever reason) no longer relevant.

--
The automated Eclipse Genie.