eclipse-platform / eclipse.platform.ui

Eclipse Platform
https://projects.eclipse.org/projects/eclipse.platform
Eclipse Public License 2.0
81 stars 184 forks source link

Race condition CopyOnWriteTextStore in results in unhandled loop event exception #1059

Closed trancexpress closed 5 months ago

trancexpress commented 1 year ago

In our automated tests, the following exception is logged sporadically:

!ENTRY org.eclipse.ui 4 0 2023-08-21 23:36:52.580
!MESSAGE Unhandled event loop exception
!STACK 0
java.lang.UnsupportedOperationException
        at org.eclipse.jface.text.CopyOnWriteTextStore$StringTextStore.replace(CopyOnWriteTextStore.java:91)
        at org.eclipse.jface.text.CopyOnWriteTextStore.replace(CopyOnWriteTextStore.java:143)
        at org.eclipse.jface.text.AbstractDocument.replace(AbstractDocument.java:1093)
        at org.eclipse.core.internal.filebuffers.SynchronizableDocument.replace(SynchronizableDocument.java:172)
        at org.eclipse.jface.text.AbstractDocument.replace(AbstractDocument.java:1118)
        at org.eclipse.core.internal.filebuffers.SynchronizableDocument.replace(SynchronizableDocument.java:160)
        at org.eclipse.text.edits.ReplaceEdit.performDocumentUpdating(ReplaceEdit.java:79)
        at org.eclipse.text.edits.TextEdit.traverseDocumentUpdating(TextEdit.java:920)
        at org.eclipse.text.edits.TextEdit.traverseDocumentUpdating(TextEdit.java:913)
        at org.eclipse.text.edits.TextEditProcessor.executeDo(TextEditProcessor.java:196)
        at org.eclipse.text.edits.TextEdit.dispatchPerformEdits(TextEdit.java:742)
        at org.eclipse.text.edits.TextEditProcessor.performEdits(TextEditProcessor.java:158)
        at org.eclipse.jface.text.RewriteSessionEditProcessor.performEdits(RewriteSessionEditProcessor.java:99)
        at org.eclipse.jdt.internal.ui.javaeditor.DocumentAdapter$ApplyTextEditCommand.run(DocumentAdapter.java:202)
        at org.eclipse.swt.widgets.RunnableLock.run(RunnableLock.java:40)
        at org.eclipse.swt.widgets.Synchronizer.runAsyncMessages(Synchronizer.java:132)
        at org.eclipse.swt.widgets.Display.runAsyncMessages(Display.java:5000)
        at org.eclipse.swt.widgets.Display.readAndDispatch(Display.java:4480)
        at org.eclipse.jface.operation.ModalContext$ModalContextThread.block(ModalContext.java:166)
        at org.eclipse.jface.operation.ModalContext.run(ModalContext.java:368)
        at org.eclipse.ui.internal.WorkbenchWindow.lambda$7(WorkbenchWindow.java:2346)
        at org.eclipse.swt.custom.BusyIndicator.showWhile(BusyIndicator.java:74)
        at org.eclipse.ui.internal.WorkbenchWindow.run(WorkbenchWindow.java:2344)
        ...

Looking at CopyOnWriteTextStore.replace(), this can only occur if CopyOnWriteTextStore.set() is called in parallel.

    @Override
    public void replace(int offset, int length, String text) {
        if (fTextStore != fModifiableTextStore) {
            String content= fTextStore.get(0, fTextStore.getLength());
            fTextStore= fModifiableTextStore;
            fTextStore.set(content);
        }
        fTextStore.replace(offset, length, text);
    }
    @Override
    public void set(String text) {
        fTextStore= new StringTextStore(text);
        fModifiableTextStore.set(""); //$NON-NLS-1$
    }

fModifiableTextStore is a GapTextStore, the exception was thrown from StringTextStore.

We should make sure CopyOnWriteTextStore is thread-safe, at least w.r.t. the race condition between replace and set.

trancexpress commented 1 year ago

@iloveeclipse are we just making the affected methods of CopyOnWriteTextStore synchronized?

Or are we trying something more clever with the synchronization? Maybe read-write locking?

iloveeclipse commented 1 year ago

Good question. Probably "synchronized" is simpler (see below):

diff --git a/bundles/org.eclipse.text/src/org/eclipse/jface/text/CopyOnWriteTextStore.java b/bundles/org.eclipse.text/src/org/eclipse/jface/text/CopyOnWriteTextStore.java
index 8c20b2a..d22dc27 100644
--- a/bundles/org.eclipse.text/src/org/eclipse/jface/text/CopyOnWriteTextStore.java
+++ b/bundles/org.eclipse.text/src/org/eclipse/jface/text/CopyOnWriteTextStore.java
@@ -122,3 +122,3 @@
    public char get(int offset) {
-       return fTextStore.get(offset);
+       return getStore().get(offset);
    }
@@ -127,3 +127,3 @@
    public String get(int offset, int length) {
-       return fTextStore.get(offset, length);
+       return getStore().get(offset, length);
    }
@@ -132,3 +132,3 @@
    public int getLength() {
-       return fTextStore.getLength();
+       return getStore().getLength();
    }
@@ -136,3 +136,3 @@
    @Override
-   public void replace(int offset, int length, String text) {
+   public synchronized void replace(int offset, int length, String text) {
        if (fTextStore != fModifiableTextStore) {
@@ -146,3 +146,3 @@
    @Override
-   public void set(String text) {
+   public synchronized void set(String text) {
        fTextStore= new StringTextStore(text);
@@ -150,2 +150,6 @@
    }
+   
+   private synchronized ITextStore getStore() {
+       return fTextStore;
+   }

With rw lock:

diff --git a/bundles/org.eclipse.text/src/org/eclipse/jface/text/CopyOnWriteTextStore.java b/bundles/org.eclipse.text/src/org/eclipse/jface/text/CopyOnWriteTextStore.java
index 8c20b2a..3fed90f 100644
--- a/bundles/org.eclipse.text/src/org/eclipse/jface/text/CopyOnWriteTextStore.java
+++ b/bundles/org.eclipse.text/src/org/eclipse/jface/text/CopyOnWriteTextStore.java
@@ -15,2 +15,4 @@

+import java.util.concurrent.locks.ReentrantReadWriteLock;
+
 import org.eclipse.core.runtime.Assert;
@@ -106,2 +108,4 @@
    private final ITextStore fModifiableTextStore;
+   
+   private final ReentrantReadWriteLock lock;

@@ -118,2 +122,3 @@
        fModifiableTextStore= modifiableTextStore;
+       lock = new ReentrantReadWriteLock();
    }
@@ -122,3 +127,8 @@
    public char get(int offset) {
-       return fTextStore.get(offset);
+       lock.readLock().lock();
+       try {
+           return fTextStore.get(offset);
+       } finally {
+           lock.readLock().unlock();
+       }
    }
@@ -127,3 +137,8 @@
    public String get(int offset, int length) {
-       return fTextStore.get(offset, length);
+       lock.readLock().lock();
+       try {
+           return fTextStore.get(offset, length);
+       } finally {
+           lock.readLock().unlock();
+       }
    }
@@ -132,3 +147,8 @@
    public int getLength() {
-       return fTextStore.getLength();
+       lock.readLock().lock();
+       try {
+           return fTextStore.getLength();
+       } finally {
+           lock.readLock().unlock();
+       }
    }
@@ -137,8 +157,13 @@
    public void replace(int offset, int length, String text) {
-       if (fTextStore != fModifiableTextStore) {
-           String content= fTextStore.get(0, fTextStore.getLength());
-           fTextStore= fModifiableTextStore;
-           fTextStore.set(content);
+       lock.writeLock().lock();
+       try {
+           if (fTextStore != fModifiableTextStore) {
+               String content= fTextStore.get(0, fTextStore.getLength());
+               fTextStore= fModifiableTextStore;
+               fTextStore.set(content);
+           }
+           fTextStore.replace(offset, length, text);
+       } finally {
+           lock.writeLock().unlock();
        }
-       fTextStore.replace(offset, length, text);
    }
@@ -147,4 +172,9 @@
    public void set(String text) {
-       fTextStore= new StringTextStore(text);
-       fModifiableTextStore.set(""); //$NON-NLS-1$
+       lock.writeLock().lock();
+       try {
+           fTextStore= new StringTextStore(text);
+           fModifiableTextStore.set(""); //$NON-NLS-1$
+       } finally {
+           lock.writeLock().unlock();
+       }
    }

Later is may be overkill, but on the other side would be not as dangerous as "hard" synchronize.

@szarnekow : WDYT?

szarnekow commented 1 year ago

I wonder how concurrent access to the store was possible at all given that we come via SynchronizableDocument

Judging from the usage pattern of all ITextStore implementations, I wouldn't assume that it's supposed to be used in a multithreaded environment. I'd rather like to understand to root of the problem instead of patching one implementation ITextStore.

szarnekow commented 1 year ago

Having said that, it seems the SynchronizableDocument isn't synchronized at all if the lockObject is null. I'm wondering, how a document was obtained that doesn't have an explicit lock set. I also wonder if it should use this if lockObject is null

org.eclipse.core.internal.filebuffers.SynchronizableDocument.replace(int, int, String) line 160

iloveeclipse commented 1 year ago

One example is org.eclipse.core.internal.filebuffers.TextFileBufferManager.createEmptyDocument(IPath, LocationKind) that returns an empty SynchronizableDocument without setting a lock.

In general, CopyOnWriteTextStore is not necessarily used from SynchronizableDocument, so making it thread safe is probably not a bad idea.

I also wonder if it should use this if lockObject is null

This could have other side effects and violate the contract of SynchronizableDocument saying "can be synchronized with a lock object" and "Initially no locking takes place."...

szarnekow commented 1 year ago

CopyonWriteTextStore

When I look at org.eclipse.jface.text.ISynchronizable it says that text related objects that can be used in multithreaded contexts must provide a means to prevent concurrent access.

ITextStore doesn't implement that interface. I don't think patching this is aligned with the overall contracts within JFace text.

TextFileBufferManager cannot really make a buffer without a synchronization (see org.eclipse.ui.editors.text.TextFileDocumentProvider.setUpSynchronization(FileInfo)). So it seems as if FileStoreTextFileBuffer is the culprit. Nevertheless it tries to maintain an annotation model along with a document. I have only read parts of the code but I feel that it's missing the lock object to prevent both becoming detached.

trancexpress commented 9 months ago

In my initial debugging, we had the following calls that were not coming from the main thread:

"ModalContext" #315 prio=6 os_prio=0 cpu=1953.11ms elapsed=1134.53s tid=0x00007fff74c5c800 nid=0x9e73 at breakpoint [0x00007fff701f8000]
   java.lang.Thread.State: RUNNABLE
        at org.eclipse.jface.text.CopyOnWriteTextStore.set(CopyOnWriteTextStore.java:148)
        at org.eclipse.jface.text.Document.<init>(Document.java:66)
        at org.eclipse.jdt.internal.corext.callhierarchy.CallLocation.initCallTextAndLineNumber(CallLocation.java:98)
        at org.eclipse.jdt.internal.corext.callhierarchy.CallLocation.getCallText(CallLocation.java:80)
"ModalContext" #315 prio=6 os_prio=0 cpu=1802.10ms elapsed=823.53s tid=0x00007fff74c5c800 nid=0x9e73 at breakpoint [0x00007fff701f7000]
   java.lang.Thread.State: RUNNABLE
        at org.eclipse.jface.text.CopyOnWriteTextStore.set(CopyOnWriteTextStore.java:148)
        at org.eclipse.jface.text.AbstractDocument.set(AbstractDocument.java:1133)
        at org.eclipse.core.internal.filebuffers.SynchronizableDocument.set(SynchronizableDocument.java:196)
        at org.eclipse.core.internal.filebuffers.ResourceTextFileBuffer.setDocumentContent(ResourceTextFileBuffer.java:531)
        at org.eclipse.core.internal.filebuffers.ResourceTextFileBuffer.initializeFileBufferContent(ResourceTextFileBuffer.java:250)
        at org.eclipse.core.internal.filebuffers.ResourceFileBuffer.create(ResourceFileBuffer.java:247)
        at org.eclipse.core.internal.filebuffers.TextFileBufferManager.connect(TextFileBufferManager.java:115)
        at org.eclipse.pde.internal.ui.refactoring.BundleManifestChange.getBundle(BundleManifestChange.java:230)
        at org.eclipse.pde.internal.ui.refactoring.BundleManifestChange.createRenameChange(BundleManifestChange.java:98)
        at org.eclipse.pde.internal.ui.refactoring.PDERenameParticipant.addBundleManifestChange(PDERenameParticipant.java:80)
        at org.eclipse.pde.internal.ui.refactoring.PDERenameParticipant.addBundleManifestChange(PDERenameParticipant.java:75)
        at org.eclipse.pde.internal.ui.refactoring.PDERenameParticipant.createChange(PDERenameParticipant.java:50)
        at org.eclipse.ltk.core.refactoring.participants.ProcessorBasedRefactoring.createChange(ProcessorBasedRefactoring.java:306)
"ModalContext" #315 prio=6 os_prio=0 cpu=143.27ms elapsed=24.52s tid=0x00007fff74c5c800 nid=0x9e73 at breakpoint [0x00007fff701f7000]
   java.lang.Thread.State: RUNNABLE
        at org.eclipse.jface.text.CopyOnWriteTextStore.set(CopyOnWriteTextStore.java:148)
        at org.eclipse.jface.text.AbstractDocument.set(AbstractDocument.java:1133)
        at org.eclipse.core.internal.filebuffers.SynchronizableDocument.set(SynchronizableDocument.java:196)
        at org.eclipse.core.internal.filebuffers.ResourceTextFileBuffer.setDocumentContent(ResourceTextFileBuffer.java:531)
        at org.eclipse.core.internal.filebuffers.ResourceTextFileBuffer.initializeFileBufferContent(ResourceTextFileBuffer.java:250)
        at org.eclipse.core.internal.filebuffers.ResourceFileBuffer.create(ResourceFileBuffer.java:247)
        at org.eclipse.core.internal.filebuffers.TextFileBufferManager.connect(TextFileBufferManager.java:115)
        at org.eclipse.jdt.internal.ui.javaeditor.DocumentAdapter.initialize(DocumentAdapter.java:302)
        at org.eclipse.jdt.internal.ui.javaeditor.DocumentAdapter.<init>(DocumentAdapter.java:292)
        at org.eclipse.jdt.internal.ui.JavaPlugin$2.createBuffer(JavaPlugin.java:398)
        at org.eclipse.jdt.internal.core.DefaultWorkingCopyOwner.createBuffer(DefaultWorkingCopyOwner.java:36)
        at org.eclipse.jdt.internal.core.CompilationUnit.openBuffer(CompilationUnit.java:1189)
        at org.eclipse.jdt.internal.core.CompilationUnit.buildStructure(CompilationUnit.java:114)
        at org.eclipse.jdt.internal.core.Openable.generateInfos(Openable.java:266)
        at org.eclipse.jdt.internal.core.JavaElement.openWhenClosed(JavaElement.java:597)

When I can, I'll check each with the comment from @szarnekow in mind.

None seem suspect, I guess I'll go over the main thread calls too...

trancexpress commented 9 months ago

The other call (coming from main thread) that doesn't have SynchronizableDocument on the stack trace is:

        at org.eclipse.jface.text.CopyOnWriteTextStore.set(CopyOnWriteTextStore.java:148)
        at org.eclipse.jface.text.Document.<init>(Document.java:66)
        at org.eclipse.jdt.internal.core.DocumentAdapter.<init>(DocumentAdapter.java:28)
        at org.eclipse.jdt.internal.core.JavaModelOperation.getDocument(JavaModelOperation.java:463)
        at org.eclipse.jdt.internal.core.JavaModelOperation.applyTextEdit(JavaModelOperation.java:208)
        at org.eclipse.jdt.internal.core.CopyResourceElementsOperation.saveContent(CopyResourceElementsOperation.java:645)
        at org.eclipse.jdt.internal.core.CopyResourceElementsOperation.processCompilationUnitResource(CopyResourceElementsOperation.java:388)
        at org.eclipse.jdt.internal.core.CopyResourceElementsOperation.processElement(CopyResourceElementsOperation.java:440)
        at org.eclipse.jdt.internal.core.MultiOperation.processElements(MultiOperation.java:168)
        at org.eclipse.jdt.internal.core.CopyResourceElementsOperation.processElements(CopyResourceElementsOperation.java:459)
        at org.eclipse.jdt.internal.core.MultiOperation.executeOperation(MultiOperation.java:95)
        at org.eclipse.jdt.internal.core.JavaModelOperation.run(JavaModelOperation.java:742)
        at org.eclipse.core.internal.resources.Workspace.run(Workspace.java:2453)
        at org.eclipse.core.internal.resources.Workspace.run(Workspace.java:2478)
        at org.eclipse.jdt.internal.core.JavaModelOperation.runOperation(JavaModelOperation.java:813)
        at org.eclipse.jdt.internal.core.JavaModel.rename(JavaModel.java:296)
        at org.eclipse.jdt.internal.core.CompilationUnit.rename(CompilationUnit.java:1347)
        at org.eclipse.jdt.internal.corext.refactoring.changes.RenameCompilationUnitChange.doRename(RenameCompilationUnitChange.java:65)
        at org.eclipse.jdt.internal.corext.refactoring.AbstractJavaElementRenameChange.perform(AbstractJavaElementRenameChange.java:92)
        at org.eclipse.ltk.core.refactoring.CompositeChange.perform(CompositeChange.java:281)
        at org.eclipse.jdt.internal.corext.refactoring.changes.DynamicValidationStateChange.access$0(DynamicValidationStateChange.java:1)
        at org.eclipse.jdt.internal.corext.refactoring.changes.DynamicValidationStateChange.lambda$0(DynamicValidationStateChange.java:105)
        at org.eclipse.jdt.internal.core.BatchOperation.executeOperation(BatchOperation.java:41)
        at org.eclipse.jdt.internal.core.JavaModelOperation.run(JavaModelOperation.java:742)
        at org.eclipse.core.internal.resources.Workspace.run(Workspace.java:2453)
        at org.eclipse.core.internal.resources.Workspace.run(Workspace.java:2478)
        at org.eclipse.jdt.core.JavaCore.run(JavaCore.java:5971)
        at org.eclipse.jdt.internal.corext.refactoring.changes.DynamicValidationStateChange.perform(DynamicValidationStateChange.java:106)
        at org.eclipse.ltk.core.refactoring.CompositeChange.perform(CompositeChange.java:281)

This seems to create its own Document object, I don't see how it would cause synchronization problems.

I don't see any FileStoreTextFileBuffer objects being created during the relevant tests.

trancexpress commented 9 months ago

Maybe the unprotected buffer is created here?

    at org.eclipse.jface.text.CopyOnWriteTextStore.<init>(CopyOnWriteTextStore.java:119)
    at org.eclipse.jface.text.Document.<init>(Document.java:52)
    at org.eclipse.jdt.internal.ui.javaeditor.DocumentAdapter.close(DocumentAdapter.java:372)
    at org.eclipse.jdt.internal.core.Openable.closeBuffer(Openable.java:94)
    at org.eclipse.jdt.internal.core.Openable.closing(Openable.java:103)
    at org.eclipse.jdt.internal.core.CompilationUnit.closing(CompilationUnit.java:254)
    at org.eclipse.jdt.internal.core.JavaModelManager.removeInfoAndChildren(JavaModelManager.java:4321)
    at org.eclipse.jdt.internal.core.JavaModelManager.discardPerWorkingCopyInfo(JavaModelManager.java:2109)
    at org.eclipse.jdt.internal.core.DiscardWorkingCopyOperation.executeOperation(DiscardWorkingCopyOperation.java:38)
    at org.eclipse.jdt.internal.core.JavaModelOperation.run(JavaModelOperation.java:742)
    at org.eclipse.jdt.internal.core.JavaModelOperation.runOperation(JavaModelOperation.java:808)
    at org.eclipse.jdt.internal.core.CompilationUnit.discardWorkingCopy(CompilationUnit.java:513)

@szarnekow , the other stack traces that create a CopyOnWriteTextStore either come from SynchronizableDocument, or are a local Document object (that is worked on and then is not propagated to other code, so I assume no concurrency issues there). Do you think this might be the issue? I'm not familiar with this area of platform code.

I guess it doesn't hurt to create a SynchronizableDocument in this code... and see if that fixes our problem (who knows).

Though I don't see how the CopyOnWriteTextStore from this Document would become the one that causes the exception from the description?...

trancexpress commented 9 months ago

Odd, during our tests I don't see calls to SynchronizableDocument.setLockObject(Object)...

Are callers of ITextFileBufferManager.createEmptyDocument(IPath, LocationKind) expected to call this, to avoid synchronization problems? E.g. code like this, from org.eclipse.jdt.internal.ui.javaeditor.DocumentAdapter.initialize():

            fDocument= manager.createEmptyDocument(fPath, fLocationKind);
            if (fDocument instanceof ISynchronizable)
                ((ISynchronizable)fDocument).setLockObject(new Object());

@szarnekow , what do you think of this change in JDT UI?

diff --git a/org.eclipse.jdt.ui/ui/org/eclipse/jdt/internal/ui/javaeditor/DocumentAdapter.java b/org.eclipse.jdt.ui/ui/org/eclipse/jdt/internal/ui/javaeditor/DocumentAdapter.java
index 5087513520..31e2d21059 100644
--- a/org.eclipse.jdt.ui/ui/org/eclipse/jdt/internal/ui/javaeditor/DocumentAdapter.java
+++ b/org.eclipse.jdt.ui/ui/org/eclipse/jdt/internal/ui/javaeditor/DocumentAdapter.java
@@ -303,6 +303,9 @@ public class DocumentAdapter implements IBuffer, IDocumentListener, ITextEditCap
                                fTextFileBuffer= manager.getTextFileBuffer(fPath, fLocationKind);
                        }
                        fDocument= fTextFileBuffer.getDocument();
+                       if (fDocument instanceof ISynchronizable sd && sd.getLockObject() == null) {
+                               ((ISynchronizable)fDocument).setLockObject(new Object());
+                       }
                } catch (CoreException x) {
                        fDocument= manager.createEmptyDocument(fPath, fLocationKind);
                        if (fDocument instanceof ISynchronizable)

https://github.com/eclipse-jdt/eclipse.jdt.ui/pull/1062

iloveeclipse commented 6 months ago

What is the state of this issue? Do we have a fix? Is https://github.com/eclipse-platform/eclipse.platform.ui/pull/1064 OK or not?

szarnekow commented 6 months ago

Sorry, I somehow missed the Github notifications here a while back. It looks like the change in JDT would be the better one - judging from the catch-clause below.

iloveeclipse commented 5 months ago

Fixed via https://github.com/eclipse-jdt/eclipse.jdt.ui/pull/1062

iloveeclipse commented 5 months ago

@szarnekow : many thanks for the review / proposed fix!