Workspace unsaved changes mystery demystified

Are you an Eclipse plug-in developer and you have seen at least once a warning saying something about unsaved changes in the previous session like the one below?

Well, I bet you did, although you probably never paid attention to it since the warning is quite harmless, although can be very annoying. Let me explain why...

The warning is generated during Eclipse startup if your workspace was not properly saved during the previous session. Not properly saved means that something bad happened like process crash, blue screen, power down, etc., and normally you would lost your work. However, Eclipse is able to detect this situation and recover. Not a very fancy recovery, but it does the job and so the warning message is very informative because it's good to know that Eclipse just recovered your work behind the scenes. So far so good.

The annoying part is that it can happen even if you are 100% sure that you closed your Eclipse the right way without any crash and all looked good when you closed it the last time. So, why Eclipse tries to recover something if there is should be nothing to recover?

The answer is that in most cases you didn't do anything wrong and the unsaved change was generated by some badly written plug-in that modified your workspace after you already asked Eclipse to shut down. If you are a curious person like I am, you will probably ask "Fine, but which of the plug-ins is the bad one?" Well, easier said than done. Especially because it happens during shutdown and you will be warned there was some unsaved change during next Eclipse startup. This is a bit too late...

The warning became so annoying that I decided to spend some time to adjust the workspace save behaviour so that we can distinguish unsaved change caused by power down from the one caused by a badly written plug-in and then find out in a semi-automatic way which plug-in is the culprit. Since Eclipse SDK 4.5 build-id I20140930-0800 additional error message will be logged if there is any code that tries to modify your workspace after you already asked Eclipse to stop. Here is an example:

!ENTRY org.eclipse.core.resources 4 10035 2014-09-30 17:27:37.511
!MESSAGE The workspace will exit with unsaved changes in this session. Snapshot requestor: org.eclipse.core.internal.events.NotificationManager$NotifyJob(Updating workspace)
!STACK 0
java.lang.RuntimeException: Scheduling workspace snapshot
 at org.eclipse.core.internal.resources.SaveManager.rememberSnapshotRequestor(SaveManager.java:553)
 at org.eclipse.core.internal.resources.SaveManager.snapshotIfNeeded(SaveManager.java:1476)
 at org.eclipse.core.internal.resources.Workspace.endOperation(Workspace.java:1499)
 at org.eclipse.core.internal.resources.Workspace.run(Workspace.java:2321)
 at org.eclipse.core.internal.events.NotificationManager$NotifyJob.run(NotificationManager.java:41)
 at org.eclipse.core.internal.jobs.Worker.run(Worker.java:55)

If you have auto-build enabled, in most cases the error will mention one of these classes:

org.eclipse.core.internal.events.AutoBuildJob
org.eclipse.core.internal.events.NotificationManager.NotifyJob

This is the code that requested additional workspace save after you manually asked Eclipse to stop but in reality, this is not the problematic part of the code. So, how can you tell which workspace operation triggered an auto-build which in turn requested additional workspace save? Here is where the "semi-" part of the solution plays a role.

Whenever you see an error saying that The workspace will exit with unsaved changes in this session., you already know that some plug-in modified your workspace without your knowledge after you asked Eclipse to stop. In order to find this plug-in you need to enable a few debug options including the new debug option for resource change notifications and then capture the console output to a file.

In the case I investigated, here is what I did:

1. Add -consoleLog to your eclipse.ini file.
2. Run Eclipse using the following command:

eclipsec.exe >> trace.txt 2>&1

3. Go to Window > Preferences > General > Tracing preference page.
4. Enable the Enable tracing option.
5. Expand the Platform Core Resources node and enable the following options:

org.eclipse.core.resources/build/delta=true
org.eclipse.core.resources/build/failure=true
org.eclipse.core.resources/build/interrupt=true
org.eclipse.core.resources/build/invoking=true
org.eclipse.core.resources/build/needbuild=true
org.eclipse.core.resources/build/needbuildstack=true
org.eclipse.core.resources/build/stacktrace=true
org.eclipse.core.resources/debug=true
org.eclipse.core.resources/notifications=true
org.eclipse.core.resources/save=true

Not all of them are strictly necessary, but since you don't want to do this more than once, it's better to gather all the data at first attempt.
6. Start using your Eclipse normally and observe the Error Log view. If you see "The workspace will exit with unsaved changes in this session." error followed by "The workspace exited with unsaved changes in the previous session;..." warning, it is time to look at the trace.txt file.

The relevant part of the trace file is between the line that says:

Tue Sep 30 17:27:34 CEST 2014 - [ModalContext] org.eclipse.core.internal.jobs.ThreadJob(Implicit Job): Full save on workspace:  starting...

and the first line that contains

java.lang.RuntimeException: Scheduling workspace snapshot

Any resource change event that happened between this two lines could be the culprit of unsaved changes so now you need to read the trace file and see which event is suspicious. In my example, it was quite easy because the following event was generated after every full save on workspace:

Type: POST_CHANGE
Build kind: 0
Resource: null
Delta:
/[*]: {}
/External Plug-in Libraries[*]: {}
/External Plug-in Libraries/.searchable[*]: {CONTENT}

What it means is that whenever I ask Eclipse to stop, some plug-in modifies the content of /External Plug-in Libraries/.searchable file as part of the save operation. This results in subsequent resource change events being populated and triggering auto-build and in the end workspace snapshot which will give the unexpected change warning during next startup. Having all this data, the only thing that is left is to find out which plug-in is responsible for /External Plug-in Libraries/.searchable and then fix it.

If you want to see an example how the whole investigation was done in practice, take a look at bug 444988 where one of the problematic plug-ins was identified and will be fixed in the near future hopefully.

Happy hunting! :)