Bug 569668 - Completion trigger is processed out of order which garbles the text
Summary: Completion trigger is processed out of order which garbles the text
Status: CLOSED DUPLICATE of bug 571746
Alias: None
Product: Platform
Classification: Eclipse Project
Component: Text (show other bugs)
Version: 4.16   Edit
Hardware: PC Linux
: P3 blocker (vote)
Target Milestone: 4.20 RC1   Edit
Assignee: Platform-Text-Inbox CLA
QA Contact:
URL:
Whiteboard:
Keywords:
Depends on:
Blocks: 101420
  Show dependency tree
 
Reported: 2020-12-11 13:47 EST by Stephan Herrmann CLA
Modified: 2021-06-08 14:10 EDT (History)
8 users (show)

See Also:


Attachments
print points (22.81 KB, application/xml)
2021-01-03 11:34 EST, Stephan Herrmann CLA
no flags Details
JUnit test (11.23 KB, text/x-java)
2021-03-11 18:56 EST, Stephan Herrmann CLA
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Stephan Herrmann CLA 2020-12-11 13:47:48 EST
Reproducible (though not 100%) in plain SDK 4.16. SDK has been freshly installed, no preferences modified, project is new (at this point it had the plugin nature, not sure if that is relevant):

Create the following class:
//---
package p.q;

import java.util.Collection;
import java.util.Set;

public class Test {
	void n(Set<Collection<?>> set, Collection<String> next) {
		
	}
}
//---

In the method body quickly type "set.add(next)" - all keyboard, nothing fancy, but quick!

The result looks like this:
//---
package p.q;

import java.util.Collection;
import java.util.Set;

public class Test {
	void n(Set<Collection<?>> set, Collection<String> next) {
		set.xt)addne(
	}
}
//---

During typing you briefly see a completion popup (around when you type '.'). Then it seems the '(' triggers insertion of a proposal, which seems to happen out of sequence producing a series of bad effects (I'm taking a few guesses here):
* '(' is not immediately added (consumed by "apply proposal"?)
* before proposal insertion adds anything to the buffer, more letters appear ("ne")
* during insertion the cursor jumps to the location right after '.'
* subsequent chars and the terminating ')' appear after the '.'

If you type faster, more letters will appear before the '(', though being typed later than '('.


Something is not well synchronized here.

Note: when I failed to reproduce, the best way to proceed was: close and re-open the editor.

Wow, I'm getting faster, this time I got "set.)addnext("

Similar effects can also be achieved, when you prepare "set.add" and then quickly press "<Ctrl+space><return>next". Again some of the letters may appear right after '.' and NO parens are inserted.

Setting major since it makes you want to switch off completion.
Comment 1 Andrey Loskutov CLA 2020-12-11 14:06:11 EST
Can you reproduce this with 4.18 RC2? I believe I've seen bugs reported & fixed recently in this area, not sure in which release.
Comment 2 Stephan Herrmann CLA 2020-12-11 14:07:45 EST
In 4.18RC2 I get "set.addnext)(" - almost better than above.
Comment 3 Stephan Herrmann CLA 2020-12-11 14:10:30 EST
(In reply to Stephan Herrmann from comment #2)
> In 4.18RC2 I get "set.addnext)(" - almost better than above.

Actually, that's just one of the variants. Those from comment 0 still occur.
Comment 4 Stephan Herrmann CLA 2020-12-11 14:12:43 EST
One more thing: in 4.18RC2 my first attempts failed to reproduce the bug. Next I imported a big project into that workspace, then I succeeded. I guess in an otherwise empty workspace you just have to be horribly fast to trigger the thing. If something slows down JDT operations a bit, reproducing sure gets easier.
Comment 5 Noopur Gupta CLA 2020-12-14 01:49:17 EST
I tried to reproduce in my master workspace by typing fast using the 4.18 RC2 build but could not reproduce it. 

Can you check/change the content assist and advanced preferences to see if it helps?
Comment 6 Stephan Herrmann CLA 2020-12-14 14:23:33 EST
(In reply to Noopur Gupta from comment #5)
> I tried to reproduce in my master workspace by typing fast using the 4.18
> RC2 build but could not reproduce it. 
> 
> Can you check/change the content assist and advanced preferences to see if
> it helps?

Some re-testing: On a different machine my SDK was still at 4.15, tried it there and did not see the problem. Looked for option of async completion, saw it's not yet present in 4.15. Could that be a hint?

Then I upgrade to 4.16, and succeeded again to reproduce. I admit on this machine I had to type quite fast. Should I be faster than you? Unbelievable! :) Perhaps you can somehow slow down your machine, e.g., by triggering a workspace build? Are you trying in a real life, fully loaded workspace?

Having a hunch re async-completion that was the first thing I disabled (& close & reopen editor), but could still reproduce.

Then I disabled all proposals except for "Java Proposals", still buggy.

Watching closer what happens in the editor, I can see that '(' is inserted with a significant delay. During this delay I continue typing and letters appear immediately, '(' is then inserted at the new cursor position and the cursor moves to after the '.' (as described above).

This goes along with the observation, that also other ways to apply a proposal sometimes have a delay, e.g., between hitting 'enter' and the editor being updated. I'll need to observe closer, in which situations exactly that happens.

Will upgrade that instance to 4.18RC2 now.
Comment 7 Stephan Herrmann CLA 2020-12-14 15:39:49 EST
(In reply to Stephan Herrmann from comment #6)
> Will upgrade that instance to 4.18RC2 now.

Done. Here the result typically looks like this: "set.addnext)(", I observed the '(' to appear 1 or 2 seconds after I finished typing. Wow! So I had plenty of time to type as many letters of the argument "next" as I pleased, before completion messes it up.

Happened with only "Java Proposals" enabled and non-blocking completion disabled.

This is on linux, here are the details:

Eclipse SDK
Version: 2020-12 (4.18)
Build id: I20201202-1800
OS: Linux, v.5.4.0-54-generic, x86_64 / gtk 3.24.20, WebKit 2.30.3
Java version: 12.0.2

Java version was different on the other machine where I first observed it.

I could *perhaps* be convinced that the trouble started after the latest OS upgrade (Kubuntu 18.4 to 20.4.1), which would perhaps point fingers at the gtk upgrade? Unfortunately, all my machines are now at the same OS version.

@Andrey, are you still on linux? What gtk version do you have?
Comment 8 Andrey Loskutov CLA 2020-12-14 16:02:02 EST
Stephan, I'm on GTK 3.22 / RHEL 7.4. I haven't heard from our users such bug reports (we are at 4.12 and 4.15). 

I haven't tried your use case yet, but I also haven't noticed anything special with code completion in recent builds either. If I would guess, I would also assume async code completion feature, added some time after 4.15, could be related.
Comment 9 Noopur Gupta CLA 2020-12-15 02:40:26 EST
(In reply to Stephan Herrmann from comment #6)
> Perhaps you can somehow slow down your machine, e.g., by triggering a
> workspace build? Are you trying in a real life, fully loaded workspace?

Yes, I am trying in my main workspace with projects from multiple Eclipse components. I tried typing with the workspace build running in parallel but could not reproduce.

I am using macOS but it probably won't be related to the OS. Adding Vikas in cc who is using Linux to try it out.

A Bugzilla query for bugs fixed in 4.15 in JDT and related to content assist shows subword completion (bug 547510) added in 4.15. You can turn it off and try. There's already a performance bug open related to that (bug 567521).
Comment 10 Stephan Herrmann CLA 2020-12-15 17:37:07 EST
To clarify: I observed the problem on 4.16 and 4.18RC2 but NOT on 4.15

Wanted, s.o. to try reproducing on Linux with SDK 4.16+ and gtk 3.24.20

I'm also puzzled by the fact that here the performance issues is not about computing proposals (as normal), but about applying a selected proposal (selected via '(' or enter). Did the non-blocking proposal feature also make application of a proposal async, even if non-blocking is disabled? Perhaps if I could continuously type at high speed, the selected proposal would never be entered? I.e. do I need to stop typing for ca. 1 sec for the proposal to be applied?
Comment 11 Noopur Gupta CLA 2020-12-16 03:06:00 EST
(In reply to Stephan Herrmann from comment #10)
> To clarify: I observed the problem on 4.16 and 4.18RC2 but NOT on 4.15
OK, got it.

> Wanted, s.o. to try reproducing on Linux with SDK 4.16+ and gtk 3.24.20
Jeff, do you have access to a gtk 3.24.20 machine? 

> I'm also puzzled by the fact that here the performance issues is not about
> computing proposals (as normal), but about applying a selected proposal
> (selected via '(' or enter). Did the non-blocking proposal feature also make
> application of a proposal async, even if non-blocking is disabled? 
I don't think so. Adding Mickael in cc.
Comment 12 Mickael Istria CLA 2020-12-16 08:13:25 EST
I'm not fast at typing so I couldn't reproduce after trying multiple variations. One things that's worth mentioning is that one probably needs the "Disable insertion triggers except 'Enter'" preference disabled to reproduce it.
I agree it's indeed a regression in ContentAssistant which was introduced when working on async content-assist. It looks like some events are not properly consumed or something like that. I have the impression that at the time you press '(', the content assist being selected may not be up-to-date and may have offsets that do not match the current caret locations.
I don't think the issue is specific to JDT, but is more generic inside Platform/JFace.
I'll try to investigate a bit more, delaying the CA processors and related code to hopefully reproduce the issue; but I'm afraid it's going to be a tricky one to reproduce and thus a tricky one to fix.
Comment 13 Mickael Istria CLA 2020-12-16 16:26:22 EST
@Stephan: note that without trying to reduce the importance of this issue, one thing you can try to reduce its likelihood of happening is to "Disable all trigger characters except 'Enter'" in preference. Note sure whether it fits your usual workflows though, but if you don't use trigger chars much, it should allow you to type even faster (apparently you're the fastest one at typing around here) without risk of such scrambled text.
Comment 14 Stephan Herrmann CLA 2021-01-02 11:53:56 EST
Here's a transscript of a conditional breakpoint at org.eclipse.jface.text.AbstractDocument.replace(int, int, String, long) with this breakpoint condition:

System.out.println("replace '"+text+"' "+pos+" * " + length +"\t"+System.currentTimeMillis()+"\t" +this);
return false;

-------------
replace '.' 116 * 0	1609599844671	org.eclipse.jface.text.projection.ProjectionDocument@125ace20
replace '.' 138 * 0	1609599844712	org.eclipse.core.internal.filebuffers.SynchronizableDocument@365291bd
replace 's' 117 * 0	1609599844898	org.eclipse.jface.text.projection.ProjectionDocument@125ace20
replace 's' 139 * 0	1609599844972	org.eclipse.core.internal.filebuffers.SynchronizableDocument@365291bd
replace 'i' 118 * 0	1609599845071	org.eclipse.jface.text.projection.ProjectionDocument@125ace20
replace 'i' 140 * 0	1609599845160	org.eclipse.core.internal.filebuffers.SynchronizableDocument@365291bd
replace 'z' 119 * 0	1609599845224	org.eclipse.jface.text.projection.ProjectionDocument@125ace20
replace 'z' 141 * 0	1609599845263	org.eclipse.core.internal.filebuffers.SynchronizableDocument@365291bd
replace 'e' 120 * 0	1609599845310	org.eclipse.jface.text.projection.ProjectionDocument@125ace20
replace 'e' 142 * 0	1609599845365	org.eclipse.core.internal.filebuffers.SynchronizableDocument@365291bd
replace '(' 143 * 0	1609599845540	org.eclipse.core.internal.filebuffers.SynchronizableDocument@365291bd
replace 'a' 117 * 0	1609599845888	org.eclipse.jface.text.projection.ProjectionDocument@125ace20
replace 'a' 139 * 0	1609599845926	org.eclipse.core.internal.filebuffers.SynchronizableDocument@365291bd
replace 'd' 118 * 0	1609599845974	org.eclipse.jface.text.projection.ProjectionDocument@125ace20
replace 'd' 140 * 0	1609599846014	org.eclipse.core.internal.filebuffers.SynchronizableDocument@365291bd
replace 'f' 119 * 0	1609599846058	org.eclipse.jface.text.projection.ProjectionDocument@125ace20
replace 'f' 141 * 0	1609599846095	org.eclipse.core.internal.filebuffers.SynchronizableDocument@365291bd
replace 'a' 120 * 0	1609599846227	org.eclipse.jface.text.projection.ProjectionDocument@125ace20
replace 'a' 142 * 0	1609599846264	org.eclipse.core.internal.filebuffers.SynchronizableDocument@365291bd
replace 'd' 121 * 0	1609599846300	org.eclipse.jface.text.projection.ProjectionDocument@125ace20
replace 'd' 143 * 0	1609599846338	org.eclipse.core.internal.filebuffers.SynchronizableDocument@365291bd
replace 'f' 122 * 0	1609599846397	org.eclipse.jface.text.projection.ProjectionDocument@125ace20
replace 'f' 144 * 0	1609599846435	org.eclipse.core.internal.filebuffers.SynchronizableDocument@365291bd
-------------

Observations: most keystrokes produce to 'replace' events, on two different documents (ProjectionDocument vs. SynchronizableDocument), BUT the trigger char '(' is not seen by the ProjectionDocument!

Also the delay between insertion into both documents looks funny to me, but I didn't check the protocol, if one document delegates to the other, or if both are updated independently.

Finally, after '(' (at offset 143) the insertion point is plain wrong (117).
Comment 15 Stephan Herrmann CLA 2021-01-02 12:20:33 EST
After many attempts I succeeded to trigger the original error with the above print point producing:

replace 's' 113 * 0	1609606380470	...ProjectionDocument@7a99d263
replace 's' 135 * 0	1609606380508	...SynchronizableDocument@6a000da8
replace 'e' 114 * 0	1609606380590	...ProjectionDocument@7a99d263
replace 'e' 136 * 0	1609606380630	...SynchronizableDocument@6a000da8
replace 't' 115 * 0	1609606380702	...ProjectionDocument@7a99d263
replace 't' 137 * 0	1609606380741	...SynchronizableDocument@6a000da8
replace '.' 116 * 0	1609606380897	...ProjectionDocument@7a99d263
replace '.' 138 * 0	1609606380939	...SynchronizableDocument@6a000da8
replace 'a' 117 * 0	1609606381080	...ProjectionDocument@7a99d263
replace 'a' 139 * 0	1609606381124	...SynchronizableDocument@6a000da8
replace 'd' 118 * 0	1609606381222	...ProjectionDocument@7a99d263
replace 'd' 140 * 0	1609606381259	...SynchronizableDocument@6a000da8
replace 'd' 119 * 0	1609606381386	...ProjectionDocument@7a99d263
replace 'd' 141 * 0	1609606381430	...SynchronizableDocument@6a000da8
replace 'n' 120 * 0	1609606381806	...ProjectionDocument@7a99d263
replace 'n' 142 * 0	1609606381852	...SynchronizableDocument@6a000da8
replace 'e' 121 * 0	1609606381917	...ProjectionDocument@7a99d263
replace 'e' 143 * 0	1609606381971	...SynchronizableDocument@6a000da8
replace 'x' 122 * 0	1609606382096	...ProjectionDocument@7a99d263
replace 'x' 144 * 0	1609606382147	...SynchronizableDocument@6a000da8
replace 't' 123 * 0	1609606382199	...ProjectionDocument@7a99d263
replace 't' 145 * 0	1609606382249	...SynchronizableDocument@6a000da8
replace ')' 124 * 0	1609606382447	...ProjectionDocument@7a99d263
replace ')' 146 * 0	1609606382488	...SynchronizableDocument@6a000da8
replace '(' 147 * 0	1609606382543	...SynchronizableDocument@6a000da8

Resulting text: set.addnext)(

Note, that inserting '(' happens more than 700ms later than inserting 'n', although the '(' was pressed BEFORE the 'n' key.

Typing several characters within a 700ms window is definitely not magic.

One more observation: while the above happened I had a println() in org.eclipse.jdt.internal.ui.text.java.AbstractJavaCompletionProposal.apply(IDocument, char, int) which was NOT triggered!

For comparison a bugfree execution printed this:

replace 's' 113 * 11	1609607328293	...ProjectionDocument@20711b02 
replace 's' 135 * 11	1609607328353	...SynchronizableDocument@4c25687b 
replace 'e' 114 * 0	1609607328445	...ProjectionDocument@20711b02 
replace 'e' 136 * 0	1609607328510	...SynchronizableDocument@4c25687b 
replace 't' 115 * 0	1609607328581	...ProjectionDocument@20711b02 
replace 't' 137 * 0	1609607328646	...SynchronizableDocument@4c25687b 
replace '.' 116 * 0	1609607328765	...ProjectionDocument@20711b02 
replace '.' 138 * 0	1609607328843	...SynchronizableDocument@4c25687b 
replace 'a' 117 * 0	1609607328920	...ProjectionDocument@20711b02 
replace 'a' 139 * 0	1609607328990	...SynchronizableDocument@4c25687b 
replace 'd' 118 * 0	1609607329063	...ProjectionDocument@20711b02 
replace 'd' 140 * 0	1609607329132	...SynchronizableDocument@4c25687b 
replace 'd' 119 * 0	1609607329205	...ProjectionDocument@20711b02 
replace 'd' 141 * 0	1609607329270	...SynchronizableDocument@4c25687b 
proposal.apply
replace 'add(next)' 139 * 3	1609607329454	...SynchronizableDocument@4c25687b 
replace 'n' 143 * 4	1609607329661	...SynchronizableDocument@4c25687b 
replace 'e' 144 * 0	1609607329798	...SynchronizableDocument@4c25687b 
replace 'x' 145 * 0	1609607330014	...SynchronizableDocument@4c25687b 
replace 't' 146 * 0	1609607330113	...SynchronizableDocument@4c25687b 

Note that instead of individually inserting single chars, the full proposal text is entered as 'add(next)'.

For good measure I checked threads: all replace is happening on thread main (probably enforced by JFace?).


QUESTION: when a trigger char is hit, is there a mechanism that by some delay/timeout etc. could cancel insertion of the proposal, and then falling back to normal key-wise document updates (but with something underfoot gone out of synch)?


If more info is needed let me know what.
Comment 16 Stephan Herrmann CLA 2021-01-03 05:01:00 EST
When running in the debugger I see the bug less frequently than in real life (approx. 1 in 10 attempts), but the following should help reproducing:

(1) leisurely type "set."
(2) after the '.' pause some hundreds of ms, then ...
(3) QUICKLY type "(n" (or "(N" to avoid having to release shift :) ).

It seems (2) is the critical factor. The only thing that needs to be "quick": the two chars in (3) must be hit with less than ~ 500ms interval.

If *feels* like this: '.' triggers computation of proposals, first one is pre-selected. Now, while additional info is computed, there's a point in time vulnerable to bad timing: '(' triggers insertion, but something is blocked, so '(' is not inserted before 'N' is typed. The deferred '(' arrives way too late (700ms after 'N'), inserts at the wrong position, and moves the cursor to a stored "current" position of several actions ago.

Ergo we would be searching for two contributing factors:
* what part of showing additional info is blocking?
* which code determines if '(' should trigger adding the selected proposal or be inserted as raw char?
* can trigger evaluation be screwed up when the display thread is blocked in the interim?

The above is in line with the observation that *sometimes* *any* means to insert a proposal can cause a dangerous delay, i.e., after Enter I need to way approx. 1 second to avoid garbage in the editor.
Comment 17 Stephan Herrmann CLA 2021-01-03 11:34:31 EST
Created attachment 285163 [details]
print points

With the attached print points I succeeded to capture an execution where events are clearly processed out of order:

replace '.' 116 * 0	1609690750789	org.eclipse.jface.text.projection.ProjectionDocument@690807a6 Thread[main,6,main]
replace '.' 138 * 0	1609690750848	org.eclipse.core.internal.filebuffers.SynchronizableDocument@c7bce0 Thread[main,6,main]
No current proposal
No current proposal
loop
task FIRST_WAIT
task FIRST_WAIT
run schedule
timer inner
task SECOND_WAIT
verifyKey VerifyEvent{StyledText {} time=714943547 data=null character='\0'=0x0 keyCode=0x20000 keyLocation=0x4000 stateMask=0x0 doit=true start=0 end=0 text=null}
task SECOND_WAIT
> triggerShowing
task IDLE
>>>> trigger showing
verifyKey VerifyEvent{StyledText {} time=714944113 data=null character='('=0x28 keyCode=0x39 keyLocation=0x0 stateMask=0x20000 doit=true start=0 end=0 text=null}
>> terminate
<< terminated
replace 'N' 117 * 0	1609690752155	org.eclipse.jface.text.projection.ProjectionDocument@690807a6 Thread[main,6,main]
replace 'N' 139 * 0	1609690752232	org.eclipse.core.internal.filebuffers.SynchronizableDocument@c7bce0 Thread[main,6,main]
replace '(' 140 * 0	1609690753197	org.eclipse.core.internal.filebuffers.SynchronizableDocument@c7bce0 Thread[main,6,main]


Please see the two verifyKey lines, one for '\0' (synthetic) and one for '(' (real keypress). The lines triggerShowing and 'trigger showing' shows how the two key events are separated by showing an additional info popup.

Then, before the '(' reaches the document, then NEXT char 'N' is inserted, such that the much delayed replace '(' will operate on unexpected document content.

This is as far as I can get. I don't understand the underlying concurrency design, so please s.o. take over from here.
Comment 18 Noopur Gupta CLA 2021-01-04 01:59:49 EST
Thanks for the details, Stephan. This should help with the investigation.
Comment 19 Mickael Istria CLA 2021-01-16 16:39:55 EST
I'm currently unassigning it because there is a workaround (disable trigger chars) and I won't work on this issue immediately. I'll come back to it when I'm cleared of higher priority duties, but in the meantime, anyone must feel free to have a look at this issue. As usual, I'll try to make reviewing incoming patches highest priority.
Comment 20 Stephan Herrmann CLA 2021-01-16 19:07:31 EST
(In reply to Mickael Istria from comment #19)
> I'm currently unassigning it because there is a workaround (disable trigger
> chars) ...

I saw you assumed that this is a workaround, but I never confirmed this. To the contrary, similar mess also happens when selecting a proposal with enter and continuing to type before the proposal was inserted (it will not be inserted)!
Comment 21 Kalyan Prasad Tatavarthi CLA 2021-03-02 02:04:07 EST
Mass move to 4.20
Comment 22 Mickael Istria CLA 2021-03-04 03:39:45 EST
I think the editor should simply ignore, or delay, key events in the time frame between proposal selection and proposal insertion complete.
Comment 23 Eclipse Genie CLA 2021-03-04 04:29:10 EST
New Gerrit change created: https://git.eclipse.org/r/c/platform/eclipse.platform.text/+/177140
Comment 24 Stephan Herrmann CLA 2021-03-08 17:48:05 EST
(In reply to Eclipse Genie from comment #23)
> New Gerrit change created:
> https://git.eclipse.org/r/c/platform/eclipse.platform.text/+/177140

I tried to test this change, but ...

... today I don't have luck reproducing the bug in a runtime eclipse (neither with nor without the patch) - so I can't tell if the patch has any effect.

However, I could still reproduce the bug on the following installed versions:

4.13, 4.14, 4.15, 4.19M3, 4.19RC2

So the bug is older than I thought (and I simply didn't go down below 4.13).


Here's spooky new detail, when I tested with this editor contents:

------------8<--------------------------
package p.q;

import java.util.Collection;
import java.util.Set;

public class Test {
	void n(Set<Collection<?>> set, Collection<String> next) {
		
	}
}
/*
Eclipse SDK
Version: 2021-03 (4.19)
Build id: I20210208-1800
OS: Linux, v.5.4.0-66-generic, x86_64 / gtk 3.24.20, WebKit 2.30.5
Java version: 11
*/
------------8<--------------------------

after editing strictly only on the empty line 8, in the end, the second to last line looked like this:

Java version:)))) ))))11

Apparently, events are not only processed out of order, chars are also inserted at a totally unrelated position!!! And it seems ')' is inserted in two different locations (both wrong) - with just one real keystroke. 


As I'm tired of manual testing, and at the same time loosing faith in the editor, let me ask: how hard is it to create an automated test that inserts key events at a controlled speed?
Comment 26 Mickael Istria CLA 2021-03-10 02:01:20 EST
I've submitted a patch which should improve it, although it's not certain it fixes the original issue.
I'm marking the issue as RESOLVED, but anyone please reopen if the issue persist or if further issues with completion proposal insertion arise in the meantime. Please also mention if this issue seems to not occur anymore, that could validate the patch was a good one.
Comment 27 Stephan Herrmann CLA 2021-03-11 12:19:20 EST
(In reply to Mickael Istria from comment #26)
> I've submitted a patch which should improve it, although it's not certain it
> fixes the original issue.
> I'm marking the issue as RESOLVED, but anyone please reopen if the issue
> persist or if further issues with completion proposal insertion arise in the
> meantime. Please also mention if this issue seems to not occur anymore, that
> could validate the patch was a good one.

I tested Build id: I20210310-2050 and, NO, it doesn't change the buggy behavior in any way.

Re-opening.

Apparently there is no shortcut around first understanding the bug, so ...

(In reply to Stephan Herrmann from comment #24)
> As I'm tired of manual testing, and at the same time loosing faith in the
> editor, let me ask: how hard is it to create an automated test that inserts
> key events at a controlled speed?

... to answer my own question "how hard": not easy, but it looks doable. I have a draft test which I'll share as soon as it succeeds to show the buggy behavior. Unfortunately, it seems this test can not be written in a portable way, since I have to modify Display.post(Event), because the completion popup otherwise intercepts my synthetic keystrokes - and that's platform specific code, with lots of calls to methods from GDK and OS :(
Comment 28 Stephan Herrmann CLA 2021-03-11 18:56:00 EST
Created attachment 285813 [details]
JUnit test

Here's a test that with some fine tuning will show the bug.

Concerning the test:
* note that this is written as a jdt.text test, though I'm not 100% who is to blame.

* never mind the test_kludge(), which was inserted only to make this test work standalone.
  Without this it would only work as part of ContentAssistTestSuite, a property which I
  inherited from ContinuousTypingCompletionTest. Go figure.

* as mentioned this test is not portable and thus will not easily make it into
  the test suite. (see previous comment about issue with Display.post()).

* it will probably need some fine tuning to show the bug on other machines. See that
  ContinuousTypingCompletionGtkTest.type(Display, String) has two constants for tuning.
  When the test is running the completion's additional info must very briefly pop up
  before the '(' is entered ('(' will not be visible for quite some while, though).

* depending on tuning it can show different symptoms, we are really looking for an outcome
  where chars appear out of order in the editor, minimal hazard: "set.addnext)(".

* when trying the same manually, preferences must be set such that '(' is indeed a trigger char.

Concerning the bug:

As mentioned, there is some connection with the additional info popup, which for large parts is the only concurrent thing in this area. *How* exactly that popup influences events I still don't know.

But: I observed where exactly things go south: 

Look at org.eclipse.jface.text.contentassist.CompletionProposalPopup.verifyKey(VerifyEvent)

Towards the end we have this block:
	if (contains(triggers, key)) {
		e.doit= false;
		hide();
		insertProposal(p, key, e.stateMask, fContentAssistSubjectControlAdapter.getSelectedRange().x);
	}

the condition is true (key is a trigger), but surprisingly inside insertProposal(), when we try to apply() the proposal, that proposal detects that it is no longer valid!

Validation happens in org.eclipse.jdt.internal.ui.text.java.AbstractJavaCompletionProposal.validate(IDocument, int, DocumentEvent), where we detect that the text in the document no longer matches the proposal.

At this point we have typed "set.ad(", so the text "ad" should perfectly match to the proposal "add(_)". 

BUT!

The world has turned under our feet: look into the hide() method shown above. It contains a call
	fProposalShell.dispose();
deeply inside there is this:
	sendEvent (SWT.Dispose);

This last call in some way spins the event loop and - voila - many subsequently typed keys cut the line and appear in the document before the '(' is fully evaluated.


This looks blatantly wrong to me and the test proves that bad things can result. 

I have no clue why this started to happen more frequently just "recently" (some months), but given the intricate dependency on timing, anything that changed timing will have had an impact. There may be a separate bug why inserting a proposal has such huge delays nowadays.

But to be fair: my initial guess that this is a direct result of async assist was likely wrong.

Finally lifting the secret about a red herring from comment 17: anybody versed in GUI events will likely recognize that "character='\0'=0x0 keyCode=0x20000" is no magic synthetic keystroke, but simply represents the left shift key, d'uh! :)
Comment 29 Mickael Istria CLA 2021-03-12 00:48:14 EST
Thanks for this thorough testing and investigation Stephan!
I did run the test locally and couldn't reproduce the issue either, test is green... So I'm wondering what's the version of GTK you're using? Maybe it can cause a difference in event handing, mine is
```
$ rpm -q gtk3
gtk3-3.24.25-2.fc33.x86_64
```

So it now seems like the issue is "only" happening in the case of trigger chars being hit. So I'm wondering, with the current state, can you reproduce the issue described in comment #20 by pressing Enter?

If I understand it right, the issue is that the chain of invocation does call `dispose` too early and that does process undesired events?
If so, one solution might be to call `display.asyncExec(() -> Stream.of(fProposalShell, fMessageTextFont, fMessageText).filter(Object::nonNull).forEach(Widget::dispose))` so the dispose is happening after other queued events and should be less likely to interfere in futher processing of insertProposals?
Comment 30 Sebastian Zarnekow CLA 2021-03-12 03:51:38 EST
Can we all please agree on leaving this open until the reporter and the affected users agree that there's no doubt left that this ticket is fixed? And if not, could you please elaborate why you resolve this as fixed given that there is a test that at least illustrates the issue for some clients?
Comment 31 Mickael Istria CLA 2021-03-12 04:15:20 EST
(In reply to Sebastian Zarnekow from comment #30)
> Can we all please agree on leaving this open until the reporter and the
> affected users agree that there's no doubt left that this ticket is fixed?
> And if not, could you please elaborate why you resolve this as fixed given
> that there is a test that at least illustrates the issue for some clients?

Yes, sure. Sorry about that, I did mark as resolved a bit as a bad reflex while I agree the issue is not resolved here.
Comment 32 Stephan Herrmann CLA 2021-03-12 14:48:36 EST
(In reply to Mickael Istria from comment #29)
> Thanks for this thorough testing and investigation Stephan!
> I did run the test locally and couldn't reproduce the issue either, test is
> green...

Please show me that you read my comment about fine tuning the timing in order to reproduce on different machines. What delays did you use? Did you see the additional info popup? For how long?

If you still can't reproduce, maybe we should compare set of installed plug-ins, JVM used, but I really believe that the delays are the main factor here.
 
> So I'm wondering what's the version of GTK you're using? Maybe it
> can cause a difference in event handing, mine is
> ```
> $ rpm -q gtk3
> gtk3-3.24.25-2.fc33.x86_64

We're going in circles, see comment 7

Frankly, I'm more and more confident that the problem is just within Eclipse. During all my debugging I didn't see any code that would behave differently on different micro versions of gtk 3.24.

> So it now seems like the issue is "only" happening in the case of trigger
> chars being hit. So I'm wondering, with the current state, can you reproduce
> the issue described in comment #20 by pressing Enter?

Comment 20 is the comment where I confirmed that pressing Enter can cause similar havoc, so what are you asking?
OTOH, the direct path to error described above depends on "contains(trigger, key)" - doesn't that (partly) answer your question?


> If I understand it right, the issue is that the chain of invocation does
> call `dispose` too early and that does process undesired events?

I didn't say "too early" but yes, this is where event ordering is broken.

> If so, one solution might be to call `display.asyncExec(() ->
> Stream.of(fProposalShell, fMessageTextFont,
> fMessageText).filter(Object::nonNull).forEach(Widget::dispose))` so the
> dispose is happening after other queued events and should be less likely to
> interfere in futher processing of insertProposals?

With my testing I already went far out off my area of expertise. I don't feel competent to assess any potential fixes, since I have no clue what bad side effects they would cause elsewhere.

I spent two entire days crafting that test. It's purpose is to help the Platform team to reproduce on their machines. I'd hate to realize that this time was spent in vain. I really put all my cards on the table.


(maybe I should program an automatic re-open trigger for this bug ;p)
Comment 33 Stephan Herrmann CLA 2021-03-13 07:32:24 EST
(In reply to Stephan Herrmann from comment #28)
> But to be fair: my initial guess that this is a direct result of async
> assist was likely wrong.

To stop the guess work on this path I inserted into the test (in setUp()):
		JavaPlugin.getDefault().getPreferenceStore().setValue(PreferenceConstants.CODEASSIST_NONUITHREAD_COMPUTATION, false);

Now it stops using AsyncCompletionProposalPopup, but the bug still occurs.
Comment 34 Stephan Herrmann CLA 2021-03-13 11:40:41 EST
I was going to report a separate bug about the slowness of working with completion (not considering computing the proposal list in the first place, i.e., filtering & inserting). 

After some scrutiny, however, all fingers are pointing towards the same location: org.eclipse.jface.text.contentassist.CompletionProposalPopup.hide()

Not only is this where keyboard events can cut the line, also this is where much of the time is spent during which more keys can be accepted and thus trigger the bug.

In my experiments hide() consumed > 600 ms. If I reduce the type ahead to 2 chars, its still > 550 ms, so there's something fishy on top of the out-of-order evaluation of key events.

Ergo: that's a delay that should never happen during typing, no matter if sync or async.

Plus: anybody still unable to reproduce the bug will increase her chances by adding some delay inside hide() (I suggest: at the top of the method).
Comment 35 Mickael Istria CLA 2021-03-13 15:58:07 EST
I tried the test moving DELAYs down to 40ms, and it was still succeeding here.
I managed to get the test failing moving delays to 30ms, but the result wasn't much of a bug: it was just not processing any completion because none was available before those 30ms.

> In my experiments hide() consumed > 600 ms. If I reduce the type ahead to 2 chars, > its still > 550 ms, so there's something fishy on top of the out-of-order
> evaluation of key events.

That could indeed be a cause of the issue here, and the reason why I cannot reproduce this issue. The hide() operation seems instantaneous here to me and doesn't leave time for other events to interfere.
Is this slowness something you feel is happening whenever closing an SWT Shell or is it specific to completion?
Comment 36 Stephan Herrmann CLA 2021-03-13 19:48:29 EST
(In reply to Mickael Istria from comment #35)
> I tried the test moving DELAYs down to 40ms, and it was still succeeding
> here.
> I managed to get the test failing moving delays to 30ms, but the result
> wasn't much of a bug: it was just not processing any completion because none
> was available before those 30ms.

There is another hint I gave: delays must be long enough to give time so the additional info popup appears. I don't know how exactly the two popups are linked - in particular regarding disposal - but from my experience the second popup has a finger in the pie.

To be on the safe side do both: delays long enough for additional info to appear before ( is sent PLUS a delay inside hide() so that more keystrokes are received before/during dispose.

It may sound like this is a very unlikely timing, but I confirm that for me it happens many, many times every day. So even if reproducing may look contrived, once you see event re-ordering that's the real bug.
Comment 37 Stephan Herrmann CLA 2021-03-14 08:20:31 EDT
(In reply to Mickael Istria from comment #29)
> If so, one solution might be to call `display.asyncExec(() ->
> Stream.of(fProposalShell, fMessageTextFont,
> fMessageText).filter(Object::nonNull).forEach(Widget::dispose))` so the
> dispose is happening after other queued events and should be less likely to
> interfere in futher processing of insertProposals?

I didn't find a location where this suggestion can be applied verbatim, so I tried different versions in this direction. In one case the test turned green, in another case I repeatedly got this variant:

resulting text expected:
        set.add(next);/*TYPE_HERE*/
but was:
        set.add(nxt);e/*TYPE_HERE*/

wow that looks "creative"! =:-0

FYI, this result was produced by modifying the call site of hide() (in verifyKey) to
	if (fProposalShell != null)
		fProposalShell.getDisplay().asyncExec(() -> hide());
	else
		hide();

Since this *looked fine* to me, there's obviously more to it than meets my eye.
Comment 38 Stephan Herrmann CLA 2021-04-15 06:05:29 EDT
ping
Comment 39 Stephan Herrmann CLA 2021-05-13 08:13:14 EDT
More information on why the issue is tricky to reproduce:

In a fresh workspace I'm observing the call
    BrowserInformationControl.isAvailable(shell)
to block the display thread for more than 1000 ms!

I can easily see that this may differ on different platforms. Since the additional info pops up "out of nowhere" (triggered by a timer, not by user interaction), I believe blocking the UI for > 1000 ms is not good, whatsoever.

But, for the bug of out-of-order event processing, it might help reproducibility if we simply add some warm up in the prologue of the test ([attachment 285813 [details]]), just explicitly initialize the browser control with the above call.

With this warmup the following parameters reliably reproduce the bug on my machine:
	int DELAY= 300;
	int DELAY_AFTER_DOT= 500;

This may still be skewed by a few debug prints in my workspace, but the ball park numbers should be usable on other machines, too.

Typical result:
expected:
    set.add(next);/*TYPE_HERE*/
but got:
    set.adnext)(/*TYPE_HERE*/
	
Three errors:
- attempt to insert the "add()" proposal failed, 2nd 'd' is missing
- '(' is inserted at a wrong position
- ';' was typed but never appeared in the document
Comment 40 Stephan Herrmann CLA 2021-05-13 09:01:13 EDT
(In reply to Stephan Herrmann from comment #39)
> - ';' was typed but never appeared in the document

Not quite. The test does not send ';', we only expect completion to insert it.
Comment 41 Stephan Herrmann CLA 2021-05-13 09:51:29 EDT
While I'm getting increasingly desperate about this issue I tried to tame CompletionProposalPopup.hide() like this:

replace:
	fProposalShell.dispose();
	fProposalShell = null;
with:
	Shell shellToDispose= fProposalShell;
	fProposalShell.getDisplay().asyncExec(() -> shellToDispose.dispose());
	fProposalShell = null;

While this avoids the out-of-order processing the result is also bad:

After inserting the proposal the editor accepts no further typing!!! You have to invoke a command like Ctrl+S to get your editor responsive again.

I should add that just recently I observed the same effect (at unrecognized patterns of my actions) in a pristine Eclipse, too: editor stops responding to keystrokes after completion.

Help!
Comment 42 Stephan Herrmann CLA 2021-05-20 16:33:51 EDT
I observed another mayhem, assumably due to the same root cause:

After selecting a completion proposal *nothing* happens.
But, in this state "Ctrl+Space Esc" inserts the selected proposal. OMG.
Happened several times (though not always) until Eclipse was restarted.
Comment 43 Kalyan Prasad Tatavarthi CLA 2021-06-04 00:56:26 EDT
Mass move out of 4.20
Comment 44 Stephan Herrmann CLA 2021-06-08 14:10:21 EDT
Gunnar's my hero! :)

I found his fix in bug 571746 via bug 567881.

After upgrading to 4.20 RC2 the garbling no longer happens.

The JUnit now stops accepting keys after the trigger char, but that could well be an issue of how I send synthetic key press. So far I couldn't observe anything suspicious when manually trying.

*** This bug has been marked as a duplicate of bug 571746 ***