Comment 1 Thomas Wolf 2019-11-20 18:02:40 EST

Seen in my development workbench: (not in tests)

org.eclipse.jgit.errors.CorruptObjectException: Object 65f847569088f4d35df73616ba5c66d18df124de is corrupt: no header
	at org.eclipse.jgit.internal.storage.file.UnpackedObject.open(UnpackedObject.java:113)
	at org.eclipse.jgit.internal.storage.file.ObjectDirectory.openLooseObject(ObjectDirectory.java:512)
	at org.eclipse.jgit.internal.storage.file.ObjectDirectory.openObject(ObjectDirectory.java:432)
	at org.eclipse.jgit.internal.storage.file.WindowCursor.open(WindowCursor.java:165)
	at org.eclipse.jgit.revwalk.RevWalk.getCachedBytes(RevWalk.java:985)
	at org.eclipse.jgit.revwalk.RevCommit.parseBody(RevCommit.java:166)
	at org.eclipse.jgit.revwalk.RevWalk.parseBody(RevWalk.java:1116)
	at org.eclipse.egit.ui.internal.history.SWTCommit.parseBody(SWTCommit.java:48)
	at org.eclipse.egit.ui.internal.history.CommitInfoBuilder.addCommit(CommitInfoBuilder.java:239)
	at org.eclipse.egit.ui.internal.history.CommitInfoBuilder.format(CommitInfoBuilder.java:118)
	at org.eclipse.egit.ui.internal.history.FormatJob.run(FormatJob.java:69)
	at org.eclipse.core.internal.jobs.Worker.run(Worker.java:63)

Comment 2 Thomas Wolf 2019-11-20 18:04:03 EST

The stack traces from comment 0 are from https://ci.eclipse.org/egit/job/egit.gerrit/944/consoleFull

Comment 3 Thomas Wolf 2019-11-20 18:11:14 EST

Filed in EGit since for now it's unclear to me where this comes from.

Will have to check what repository we have in that SWTCommit. If it's the real repository (not the RepositoryHandle), something would have to be done about that so that we don't leak it there.

Comment 4 Thomas Wolf 2019-11-20 18:17:45 EST

(In reply to Thomas Wolf from comment #3)
> Filed in EGit since for now it's unclear to me where this comes from.
> 
> Will have to check what repository we have in that SWTCommit. If it's the
> real repository (not the RepositoryHandle), something would have to be done
> about that so that we don't leak it there.

It _is_ the RepositoryHandle, so that bit looks OK.  Next will have to check if using such a handle in WindowCache may cause trouble.

Comment 5 Thomas Wolf 2019-11-21 03:31:33 EST

From https://ci.eclipse.org/egit/job/egit.gerrit/949/artifact/org.eclipse.egit.ui.test/target/work/data/.metadata/.log :

!ENTRY org.eclipse.egit.ui 4 0 2019-11-21 08:17:22.694
!MESSAGE Error parsing body
!STACK 0
org.eclipse.jgit.errors.CorruptObjectException: Object 5815b54a14d5af58eeb225947b55e844b28b7041 is corrupt: invalid type
	at org.eclipse.jgit.lib.Constants.decodeTypeString(Constants.java:634)
	at org.eclipse.jgit.internal.storage.file.UnpackedObject.open(UnpackedObject.java:117)
	at org.eclipse.jgit.internal.storage.file.ObjectDirectory.openLooseObject(ObjectDirectory.java:512)
	at org.eclipse.jgit.internal.storage.file.ObjectDirectory.openObject(ObjectDirectory.java:432)
	at org.eclipse.jgit.internal.storage.file.WindowCursor.open(WindowCursor.java:165)
	at org.eclipse.jgit.revwalk.RevWalk.getCachedBytes(RevWalk.java:985)
	at org.eclipse.jgit.revwalk.RevCommit.parseBody(RevCommit.java:166)
	at org.eclipse.jgit.revwalk.RevWalk.parseBody(RevWalk.java:1116)
	at org.eclipse.egit.ui.internal.history.SWTCommit.parseBody(SWTCommit.java:48)
	at org.eclipse.egit.ui.internal.history.GraphLabelProvider.getColumnText(GraphLabelProvider.java:42)
	at org.eclipse.jface.viewers.TableColumnViewerLabelProvider.update(TableColumnViewerLabelProvider.java:66)
	at org.eclipse.jface.viewers.ViewerColumn.refresh(ViewerColumn.java:141)
	at org.eclipse.jface.viewers.AbstractTableViewer.doUpdateItem(AbstractTableViewer.java:389)
	at org.eclipse.jface.viewers.StructuredViewer$UpdateItemSafeRunnable.run(StructuredViewer.java:474)
	at org.eclipse.core.runtime.SafeRunner.run(SafeRunner.java:42)
	at org.eclipse.ui.internal.JFaceUtil$1.run(JFaceUtil.java:50)
	at org.eclipse.jface.util.SafeRunnable.run(SafeRunnable.java:173)
	at org.eclipse.jface.viewers.StructuredViewer.updateItem(StructuredViewer.java:2170)
	at org.eclipse.jface.viewers.AbstractTableViewer$VirtualManager.lambda$0(AbstractTableViewer.java:95)
	at org.eclipse.swt.widgets.EventTable.sendEvent(EventTable.java:84)
	at org.eclipse.swt.widgets.Display.sendEvent(Display.java:5227)
	at org.eclipse.swt.widgets.Widget.sendEvent(Widget.java:1340)
	at org.eclipse.swt.widgets.Widget.sendEvent(Widget.java:1366)
	at org.eclipse.swt.widgets.Widget.sendEvent(Widget.java:1349)
	at org.eclipse.swt.widgets.Table.checkData(Table.java:270)
	at org.eclipse.swt.widgets.TableItem.getText(TableItem.java:666)
	at org.eclipse.jface.viewers.AbstractTableViewer.virtualSetSelectionToWidget(AbstractTableViewer.java:946)
	at org.eclipse.jface.viewers.AbstractTableViewer.setSelectionToWidget(AbstractTableViewer.java:837)
	at org.eclipse.jface.viewers.StructuredViewer.setSelectionToWidget(StructuredViewer.java:1770)
	at org.eclipse.jface.viewers.StructuredViewer.setSelection(StructuredViewer.java:1726)
	at org.eclipse.jface.viewers.TableViewer.setSelection(TableViewer.java:162)
	at org.eclipse.egit.ui.internal.history.CommitGraphTable.selectCommit(CommitGraphTable.java:384)
	at org.eclipse.egit.ui.internal.history.GitHistoryPage$8.run(GitHistoryPage.java:2634)
	at org.eclipse.swt.widgets.RunnableLock.run(RunnableLock.java:35)
	at org.eclipse.swt.widgets.Synchronizer.runAsyncMessages(Synchronizer.java:182)
	at org.eclipse.swt.widgets.Display.runAsyncMessages(Display.java:4536)
	at org.eclipse.swt.widgets.Display.readAndDispatch(Display.java:4154)
	at org.eclipse.egit.ui.test.TestUtil.processUIEvents(TestUtil.java:256)
	at org.eclipse.egit.ui.test.TestUtil.processUIEvents(TestUtil.java:242)
	at org.eclipse.egit.ui.test.TestUtil$1.run(TestUtil.java:277)
	at org.eclipse.swt.widgets.RunnableLock.run(RunnableLock.java:35)
	at org.eclipse.swt.widgets.Synchronizer.runAsyncMessages(Synchronizer.java:182)
	at org.eclipse.swt.widgets.Display.runAsyncMessages(Display.java:4536)
	at org.eclipse.swt.widgets.Display.readAndDispatch(Display.java:4154)
	at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine$4.run(PartRenderingEngine.java:1121)
	at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:336)
	at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.run(PartRenderingEngine.java:1022)
	at org.eclipse.e4.ui.internal.workbench.E4Workbench.createAndRunUI(E4Workbench.java:150)
	at org.eclipse.ui.internal.Workbench$5.run(Workbench.java:693)
	at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:336)
	at org.eclipse.ui.internal.Workbench.createAndRunWorkbench(Workbench.java:610)
	at org.eclipse.ui.PlatformUI.createAndRunWorkbench(PlatformUI.java:148)
	at org.eclipse.ui.internal.ide.application.IDEApplication.start(IDEApplication.java:138)
	at org.eclipse.tycho.surefire.osgibooter.UITestApplication.runApplication(UITestApplication.java:31)
	at org.eclipse.tycho.surefire.osgibooter.AbstractUITestApplication.run(AbstractUITestApplication.java:120)
	at org.eclipse.tycho.surefire.osgibooter.UITestApplication.start(UITestApplication.java:37)
	at org.eclipse.equinox.internal.app.EclipseAppHandle.run(EclipseAppHandle.java:196)
	at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.runApplication(EclipseAppLauncher.java:134)
	at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.start(EclipseAppLauncher.java:104)
	at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:388)
	at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:243)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.eclipse.equinox.launcher.Main.invokeFramework(Main.java:673)
	at org.eclipse.equinox.launcher.Main.basicRun(Main.java:610)
	at org.eclipse.equinox.launcher.Main.run(Main.java:1519)
	at org.eclipse.equinox.launcher.Main.main(Main.java:1492)

!ENTRY org.eclipse.egit.ui 4 0 2019-11-21 08:17:22.701
!MESSAGE Object 5815b54a14d5af58eeb225947b55e844b28b7041 is corrupt: bad stream
!STACK 0
org.eclipse.jgit.errors.CorruptObjectException: Object 5815b54a14d5af58eeb225947b55e844b28b7041 is corrupt: bad stream
	at org.eclipse.jgit.internal.storage.file.UnpackedObject.open(UnpackedObject.java:185)
	at org.eclipse.jgit.internal.storage.file.ObjectDirectory.openLooseObject(ObjectDirectory.java:512)
	at org.eclipse.jgit.internal.storage.file.ObjectDirectory.openObject(ObjectDirectory.java:432)
	at org.eclipse.jgit.internal.storage.file.WindowCursor.open(WindowCursor.java:165)
	at org.eclipse.jgit.revwalk.RevWalk.getCachedBytes(RevWalk.java:985)
	at org.eclipse.jgit.revwalk.RevCommit.parseBody(RevCommit.java:166)
	at org.eclipse.jgit.revwalk.RevWalk.parseBody(RevWalk.java:1116)
	at org.eclipse.egit.ui.internal.history.SWTCommit.parseBody(SWTCommit.java:48)
	at org.eclipse.egit.ui.internal.history.CommitInfoBuilder.addCommit(CommitInfoBuilder.java:239)
	at org.eclipse.egit.ui.internal.history.CommitInfoBuilder.format(CommitInfoBuilder.java:118)
	at org.eclipse.egit.ui.internal.history.FormatJob.run(FormatJob.java:69)
	at org.eclipse.core.internal.jobs.Worker.run(Worker.java:55)

!ENTRY org.eclipse.egit.ui 4 0 2019-11-21 08:17:23.368
!MESSAGE Error parsing body
!STACK 0
org.eclipse.jgit.errors.CorruptObjectException: Object 5815b54a14d5af58eeb225947b55e844b28b7041 is corrupt: bad stream
	at org.eclipse.jgit.internal.storage.file.UnpackedObject.checkValidEndOfStream(UnpackedObject.java:261)
	at org.eclipse.jgit.internal.storage.file.UnpackedObject.open(UnpackedObject.java:137)
	at org.eclipse.jgit.internal.storage.file.ObjectDirectory.openLooseObject(ObjectDirectory.java:512)
	at org.eclipse.jgit.internal.storage.file.ObjectDirectory.openObject(ObjectDirectory.java:432)
	at org.eclipse.jgit.internal.storage.file.WindowCursor.open(WindowCursor.java:165)
	at org.eclipse.jgit.revwalk.RevWalk.getCachedBytes(RevWalk.java:985)
	at org.eclipse.jgit.revwalk.RevCommit.parseBody(RevCommit.java:166)
	at org.eclipse.jgit.revwalk.RevWalk.parseBody(RevWalk.java:1116)
	at org.eclipse.egit.ui.internal.history.SWTCommit.parseBody(SWTCommit.java:48)
	at org.eclipse.egit.ui.internal.history.GraphLabelProvider.getColumnText(GraphLabelProvider.java:42)
	at org.eclipse.jface.viewers.TableColumnViewerLabelProvider.update(TableColumnViewerLabelProvider.java:66)
	at org.eclipse.jface.viewers.ViewerColumn.refresh(ViewerColumn.java:141)
	at org.eclipse.jface.viewers.AbstractTableViewer.doUpdateItem(AbstractTableViewer.java:389)
	at org.eclipse.jface.viewers.StructuredViewer$UpdateItemSafeRunnable.run(StructuredViewer.java:474)
	at org.eclipse.core.runtime.SafeRunner.run(SafeRunner.java:42)
	at org.eclipse.ui.internal.JFaceUtil$1.run(JFaceUtil.java:50)
	at org.eclipse.jface.util.SafeRunnable.run(SafeRunnable.java:173)
	at org.eclipse.jface.viewers.StructuredViewer.updateItem(StructuredViewer.java:2170)
	at org.eclipse.jface.viewers.AbstractTableViewer$VirtualManager.lambda$0(AbstractTableViewer.java:95)
	at org.eclipse.swt.widgets.EventTable.sendEvent(EventTable.java:84)
	at org.eclipse.swt.widgets.Display.sendEvent(Display.java:5227)
	at org.eclipse.swt.widgets.Widget.sendEvent(Widget.java:1340)
	at org.eclipse.swt.widgets.Widget.sendEvent(Widget.java:1366)
	at org.eclipse.swt.widgets.Widget.sendEvent(Widget.java:1349)
	at org.eclipse.swt.widgets.Table.checkData(Table.java:270)
	at org.eclipse.swt.widgets.TableItem.getText(TableItem.java:666)
	at org.eclipse.jface.viewers.AbstractTableViewer.virtualSetSelectionToWidget(AbstractTableViewer.java:946)
	at org.eclipse.jface.viewers.AbstractTableViewer.setSelectionToWidget(AbstractTableViewer.java:837)
	at org.eclipse.jface.viewers.StructuredViewer.setSelectionToWidget(StructuredViewer.java:1770)
	at org.eclipse.jface.viewers.StructuredViewer.setSelection(StructuredViewer.java:1726)
	at org.eclipse.jface.viewers.TableViewer.setSelection(TableViewer.java:162)
	at org.eclipse.egit.ui.internal.history.CommitGraphTable.selectCommit(CommitGraphTable.java:390)
	at org.eclipse.egit.ui.internal.history.GitHistoryPage$8.run(GitHistoryPage.java:2634)
	at org.eclipse.swt.widgets.RunnableLock.run(RunnableLock.java:35)
	at org.eclipse.swt.widgets.Synchronizer.runAsyncMessages(Synchronizer.java:182)
	at org.eclipse.swt.widgets.Display.runAsyncMessages(Display.java:4536)
	at org.eclipse.swt.widgets.Display.readAndDispatch(Display.java:4154)
	at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine$4.run(PartRenderingEngine.java:1121)
	at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:336)
	at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.run(PartRenderingEngine.java:1022)
	at org.eclipse.e4.ui.internal.workbench.E4Workbench.createAndRunUI(E4Workbench.java:150)
	at org.eclipse.ui.internal.Workbench$5.run(Workbench.java:693)
	at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:336)
	at org.eclipse.ui.internal.Workbench.createAndRunWorkbench(Workbench.java:610)
	at org.eclipse.ui.PlatformUI.createAndRunWorkbench(PlatformUI.java:148)
	at org.eclipse.ui.internal.ide.application.IDEApplication.start(IDEApplication.java:138)
	at org.eclipse.tycho.surefire.osgibooter.UITestApplication.runApplication(UITestApplication.java:31)
	at org.eclipse.tycho.surefire.osgibooter.AbstractUITestApplication.run(AbstractUITestApplication.java:120)
	at org.eclipse.tycho.surefire.osgibooter.UITestApplication.start(UITestApplication.java:37)
	at org.eclipse.equinox.internal.app.EclipseAppHandle.run(EclipseAppHandle.java:196)
	at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.runApplication(EclipseAppLauncher.java:134)
	at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.start(EclipseAppLauncher.java:104)
	at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:388)
	at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:243)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.eclipse.equinox.launcher.Main.invokeFramework(Main.java:673)
	at org.eclipse.equinox.launcher.Main.basicRun(Main.java:610)
	at org.eclipse.equinox.launcher.Main.run(Main.java:1519)
	at org.eclipse.equinox.launcher.Main.main(Main.java:1492)

!ENTRY org.eclipse.egit.ui 4 0 2019-11-21 08:17:58.470
!MESSAGE Unexpected end of ZLIB input stream
!STACK 0
java.io.EOFException: Unexpected end of ZLIB input stream
	at java.util.zip.InflaterInputStream.fill(InflaterInputStream.java:240)
	at java.util.zip.InflaterInputStream.read(InflaterInputStream.java:158)
	at org.eclipse.jgit.util.IO.readFully(IO.java:234)
	at org.eclipse.jgit.internal.storage.file.UnpackedObject.open(UnpackedObject.java:136)
	at org.eclipse.jgit.internal.storage.file.ObjectDirectory.openLooseObject(ObjectDirectory.java:512)
	at org.eclipse.jgit.internal.storage.file.ObjectDirectory.openObject(ObjectDirectory.java:432)
	at org.eclipse.jgit.internal.storage.file.WindowCursor.open(WindowCursor.java:165)
	at org.eclipse.jgit.revwalk.RevWalk.getCachedBytes(RevWalk.java:985)
	at org.eclipse.jgit.revwalk.RevCommit.parseBody(RevCommit.java:166)
	at org.eclipse.jgit.revwalk.RevWalk.parseBody(RevWalk.java:1116)
	at org.eclipse.egit.ui.internal.history.SWTCommit.parseBody(SWTCommit.java:48)
	at org.eclipse.egit.ui.internal.history.CommitInfoBuilder.addCommit(CommitInfoBuilder.java:239)
	at org.eclipse.egit.ui.internal.history.CommitInfoBuilder.format(CommitInfoBuilder.java:113)
	at org.eclipse.egit.ui.internal.history.FormatJob.run(FormatJob.java:69)
	at org.eclipse.core.internal.jobs.Worker.run(Worker.java:55)

Comment 6 Thomas Wolf 2019-11-21 07:12:46 EST

Occurs in my workbench with

EGit 5.6.0.201911161709
JGit 5.6.0.201911161456

Comment 7 Thomas Wolf 2019-11-21 09:56:52 EST

In the tests this occurs frequently in HistoryViewTest. (Unsurprisingly, since it appears to be related to the history view.) Seen it in testSelectBranch, and also in testSelectShownRefs.

BTW, it would be really helpful if the JGit error message included the filename!

Comment 8 Thomas Wolf 2019-11-21 15:00:35 EST

This looks like a concurrency problem, and there's a massive one in the GitHistoryPage.

The commit table is a virtual table. So the code avoids parsing commit bodies when commit are generated in GitHistoryWalk but does so in the GraphlabelProvider. But now there are two threads that may operate on the same RevWalk: the UI thread and the thread running the GitHistoryJob.

But a RevWalk is not thread safe.

Then there is the display of the commit message. That's also computed asynchronously in the FormatJob. But that one also parses the commit, and uses
the same RevWalk, too.

So we even have three threads that may try to use the same RevWalk and thus the same ObjectReader to read a commit.

Additionally, there's also the FindToolbarJob, which *also* calls SWTCommit.parseBody(). Plus the SWTPlotRenderer.

Finally, if the FormatJob called SWTCommit.parseBody() after a new GitHistoryJob had been created and the old one as already been disposed, it'd use an already closed RevWalk.

All this doesn't look correct at all to me.

A simple fix is to parse the commit body in GitHistoryWalk.next() before returning the commit. Then the two other threads will never call parseBody() on the same walk. But that may increase memory consumption quite a bit if the history is long. An alternative is to indeed load the commit body in SWTCommit.parseBody(), but use a new walk. Since the commit headers are already parsed, that will work and will just add the raw bytes.

Both solutions avoid these exceptions.

Comment 9 Eclipse Genie 2019-11-21 15:16:51 EST

New Gerrit change created: https://git.eclipse.org/r/153144

Comment 10 Eclipse Genie 2019-11-22 02:01:11 EST

Gerrit change https://git.eclipse.org/r/153144 was merged to [master].
Commit: http://git.eclipse.org/c/egit/egit.git/commit/?id=09d767cf291b7065d669a508351955b886ad79d3

Comment 11 Michael Keppler 2019-11-22 02:02:47 EST

I had only seen that exception once, as far as I can remember, therefore I had assumed actual corrupt data on my side.

Comment 12 Thomas Wolf 2019-11-22 02:10:41 EST

(In reply to Michael Keppler from comment #11)
> I had only seen that exception once, as far as I can remember, therefore I
> had assumed actual corrupt data on my side.

Similar here, except that all operations on the affected repository and the commits mentioned in the exception message worked, so clearly the repo was not corrupted at all.

What I don't understand is why this problem didn't surface earlier. The concurrent access to this RevWalk was introduced 7 years ago. I had never had this in my Eclipse, only seen it very rarely in test logs. But since the RepositoryHandle was introduced in commit 528a53b27, we seem to hit this problem far more often. I've double- and triple-checked that commit and can't see anything wrong with it.