search

vazexqi / CodingSpectator

Watches and analyzes code edits in the Eclipse IDE non-invasively
http://codingspectator.cs.illinois.edu
Other
20 stars 14 forks source link

CodingTracker replayer throws an NPE #247

Closed reprogrammer closed 13 years ago

reprogrammer commented 13 years ago

The replayer of CodingTracker fails with the following exception on "cs-504/b7709c12-ba60-4d6b-ad92-f370765d6fce/1.0.0.201105300951/codingtracker/codechanges.txt".

eclipse.buildId=M20110210-1200
java.version=1.6.0_24
java.vendor=Sun Microsystems Inc.
BootLoader constants: OS=linux, ARCH=x86_64, WS=gtk, NL=en_US
Framework arguments:  -product org.eclipse.epp.package.rcp.product
Command-line arguments:  -product org.eclipse.epp.package.rcp.product -data /workspace/.metadata/.plugins/org.eclipse.pde.core/CodingSpectator/dev.properties -os linux -ws gtk -arch x86_64 -consoleLog

Error
Thu Jun 09 11:37:41 CDT 2011
Unhandled event loop exception

org.eclipse.swt.SWTException: Failed to execute runnable (java.lang.RuntimeException: java.lang.NullPointerException)
at org.eclipse.swt.SWT.error(SWT.java:4083)
at org.eclipse.swt.SWT.error(SWT.java:3998)
at org.eclipse.swt.widgets.Synchronizer.runAsyncMessages(Synchronizer.java:137)
at org.eclipse.swt.widgets.Display.runAsyncMessages(Display.java:3515)
at org.eclipse.swt.widgets.Display.readAndDispatch(Display.java:3164)
at org.eclipse.ui.internal.Workbench.runEventLoop(Workbench.java:2640)
at org.eclipse.ui.internal.Workbench.runUI(Workbench.java:2604)
at org.eclipse.ui.internal.Workbench.access$4(Workbench.java:2438)
at org.eclipse.ui.internal.Workbench$7.run(Workbench.java:671)
at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:332)
at org.eclipse.ui.internal.Workbench.createAndRunWorkbench(Workbench.java:664)
at org.eclipse.ui.PlatformUI.createAndRunWorkbench(PlatformUI.java:149)
at org.eclipse.ui.internal.ide.application.IDEApplication.start(IDEApplication.java:115)
at org.eclipse.equinox.internal.app.EclipseAppHandle.run(EclipseAppHandle.java:196)
at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.runApplication(EclipseAppLauncher.java:110)
at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.start(EclipseAppLauncher.java:79)
at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:369)
at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:179)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.eclipse.equinox.launcher.Main.invokeFramework(Main.java:620)
at org.eclipse.equinox.launcher.Main.basicRun(Main.java:575)
at org.eclipse.equinox.launcher.Main.run(Main.java:1408)
at org.eclipse.equinox.launcher.Main.main(Main.java:1384)
Caused by: java.lang.RuntimeException: java.lang.NullPointerException
at edu.illinois.codingtracker.replaying.UserOperationReplayer.replayAndAdvanceCurrentUserOperation(UserOperationReplayer.java:226)
at edu.illinois.codingtracker.replaying.UserOperationReplayer.access$3(UserOperationReplayer.java:213)
at edu.illinois.codingtracker.replaying.UserOperationReplayer$UserOperationExecutionThread$1.run(UserOperationReplayer.java:321)
at org.eclipse.swt.widgets.RunnableLock.run(RunnableLock.java:35)
at org.eclipse.swt.widgets.Synchronizer.runAsyncMessages(Synchronizer.java:134)
... 23 more
Caused by: java.lang.NullPointerException
at edu.illinois.codingtracker.operations.conflicteditors.SavedConflictEditorOperation.replay(SavedConflictEditorOperation.java:61)
at edu.illinois.codingtracker.replaying.UserOperationReplayer.replayAndAdvanceCurrentUserOperation(UserOperationReplayer.java:223)
... 27 more
Wanderer777 commented 13 years ago

The above problem is due to a conflict editor save operation that is not preceded by a corresponding conflict editor open operation. It is not clear how this scenario can happen, but just checking the existence of the saved conflict editor and proceeding without saving it if it does not exist (see the above commit) helped to continue replaying the sequence of user operations recorded for participant cs-504.

The only other data anomaly was caused by 2 duplicated code edits: the same code change event was recorded twice. Again, it is not clear how this can happen since CodingTracker registers itself on a newly created text buffers and the above scenario would mean that either two buffers share the same document or the same buffer sends its creation notification twice. In both cases this would be an Eclipse bug. Maybe there are some other scenarios, but I have no idea how to reproduce this problem. Anyway, so far this is the only such case out of all recorded operations of all participants that I replayed. For this particular case just removing two duplicated user operations (with timestamps 1307782748997 and 1307782749001) helped to replay the sequence till the end. If we observe this more often, then instead of manual fixing we will implement a postprocessing step that would eliminate duplicated user operations.

reprogrammer commented 13 years ago

@Wanderer777: Have you tested the scenario where the user opens a file in two editors? You can open a new editor from an existing editor by right clicking on the title of the the editor and selecting "New Editor".

Wanderer777 commented 13 years ago

@reprogrammer: Yes, I tested such scenario - it was one of the first scenarios that I used when I just started working on CodingTracker. There are different ways in which you can open several editors on the same file and with the exception of conflict (compare) editors, all text editors share the same document (that is why if you change the text in one editor, you can see your changes in all other editors of the same file), and there is a single buffer created for it regardless of the number of editors connected to this file. Conflict editors are different, because each has its own document, and CodingTracker uses a different mechanism to track changes to documents of conflict editors.

Wanderer777 commented 13 years ago

I found the same data anomaly in the recorded operation sequence for participant cs-506. The operations with timestamps 1308238981896, 1308238981899, 1308446718671, and 1308446718679 are duplicates that have to be removed for the correct operation sequence replaying. I still can not reproduce this problem, but it looks more and more as a possible Eclipse bug. In particular, duplicates with timestamps 1308446718671 and 1308446718679 belong to the same logical sub-sequence of code changes (adding a class that implements HttpSession using Eclipse code generation), but only the first two operations were duplicated while the multiple following operations of this logical sub-sequence of code changes were recorded correctly. Note that this whole logical sub-sequence of code changes is a result of the same "add inner class" high level action, which is performed by Eclipse automatically. This suggests that there is a single document listener, which receives each of the first two event notifications twice (which is a bug), while the following event notifications are received correctly (i.e. just once).

So far, there are very few instances of this problem in the recorded sequences and they were relatively easy to detect and fix. If this problem becomes more pervasive, we would need to implement an automatic fixer as a postprocessing step.

reprogrammer commented 13 years ago

@Wanderer777: We're going to analyze the current data. And, our analysis depends on CodingTracker log files, too. If you think some problems in CodingTracker log files need to be manually fixed or you don't have automated fixes for them, we'll ask you to store the fixed log files into our internal SVN repository.

Wanderer777 commented 13 years ago

@reprogrammer: Sure, I can do that. But the problem is that our participants will keep uploading new data. And to analyze the most recent data, we will have to fix the same operations again. Then again, again, and again for the following uploads. So, either you will be restricted to the version of data that I fixed and stored in our SVN repository, or I will have to repeat the manual fixes over and over again, which does not sound right to me.

reprogrammer commented 13 years ago

@Wanderer777: As you suggested before, I think it's a good idea to automate the fix if you think the overhead of manual fixing is high.

Wanderer777 commented 13 years ago

@reprogrammer: In this particular case the overhead of manual fixing is very low if I do it only once - for the final upload of the recorded operations (i.e. at the end of the study for these two participants, or when they switch to a new CodingSpectator version and thus, start new sequences).

reprogrammer commented 13 years ago

@Wanderer777: We'd like to analyze the data continuously because finding a problem at the end of the study will be too late.

Wanderer777 commented 13 years ago

@reprogrammer: The duplication problem is solved by the above commit, so postprocessing is not required any more. But lets keep this issue open for a while since it contains information on how to manually fix 2 operation sequences that contain duplicates.

reprogrammer commented 13 years ago

@Wanderer777: Postprocessing is still required for the existing data, isn't it?

Wanderer777 commented 13 years ago

@reprogrammer: There are just a couple of instances of this problem in the already collected data that I am aware of. And I think this is too little to justify an automated fix.

Wanderer777 commented 13 years ago

This issue is fixed. The required manual fixes in the operation sequences that were recorded before this fix are reported in issue #263.