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

Submissions may fail due to missing files #299

Closed reprogrammer closed 13 years ago

reprogrammer commented 13 years ago

We've received reports from our participants about failures to submit their data because of some missing files that had been added to the working copy.

Participant cs-118 reported the following.

Failed to upload CodingSpectator data.
org.tmatesoft.svn.core.SVNException: svn: Commit failed (details follow):
svn: '/path/to/workspace/.metadata/.plugins/edu.illinois.codingspectator.data/1.0.0.201105300951/refactorings/refactoring-problems.log'
is scheduled for addition, but is missing

And, participant cs-509 reported the following:

Failed to upload CodingSpectator data.
org.tmatesoft.svn.core.SVNException: svn: Commit failed (details follow):
svn: '/path/to/workspace/.metadata/.plugins/edu.illinois.codingspectator.data/1.0.0.201107172332/codingtracker/codechanges.txt'
is scheduled for addition, but is missing
reprogrammer commented 13 years ago

@Wanderer777 said the following:

It looks that the file disappeared after our SVN client added files to be uploaded, but before locking them for the upload. This corresponds to the older preSubmit notification. SafeRecorder code that handles this notification does not delete the main record file, but rather switches to a temporary file, and I wonder if this could trigger the file system failure. Also, I think that our latest change to SafeRecorder, in which we store files outside the watched folder and copy them there only before the commit (and thus, before SVN client adds files to be uploaded), could mitigate this problem, since we would not create new files in between SVN add and commit operations.

reprogrammer commented 13 years ago

@Wanderer777: Even though our forthcoming change in data submission may address this issue, we should still investigate this problem and find the root cause of it.

Wanderer777 commented 13 years ago

@reprogrammer: I have no particular reason to believe that this problem is caused by SafeRecorder switching from the main file to a temporary file (please see SafeRecorder#aboutToSubmit()) since it does not touch the main file. But it is an IO operation, so hypothetically, it might trigger a failure of a faulty file system. Additionally, CodingTracker might write to the main file before executing SafeRecorder#aboutToSubmit() but after the file was added for the uploading. But again, it is not clear why this operation could erase the file.

reprogrammer commented 13 years ago

@Wanderer777: I couldn't find SafeRecorder#aboutToSubmit(). Did you mean SafeRecorder#commitStarted?

What happens if SafeRecorder#commitCompleted gets invoked without a preceding SafeRecorder#commitStarted. Could codechanges.txt get deleted in this scenario?

Wanderer777 commented 13 years ago

@reprogrammer: Sorry, SafeRecorder#aboutToSubmit() is in codingtracker branch, which was not merged into the master yet. Previously, this method was named SafeRecorder#commitStarted and had a different functionality.

You are right, if SafeRecorder#commitCompleted is invoked without a preceding SafeRecorder#commitStarted, that would have a disastrous effect of deleting the main record file. I remember we discussed the contract of these notifications quite a while ago, trying to guarantee that they are delivered correctly. Looking at the current implementation of Submitter#submit(), I can see that the scenario you described can indeed happen, and I wonder if in some previous implementation of Submitter#submit() we ensured that SubmitterListener.postSubmit(boolean) would not be sent without a preceding SubmitterListener.preSubmit.

At the same time, it would not explain the above problem of the participant, since in such a scenario the main record file would be deleted only after the uploading is over (regardless of whether it failed or succeeded). Anyway, in the latest implementation of SafeRecorder (please see codingtracker branch), in which we store the record files outside of the watched directory, such a scenario is not possible, because SafeRecorder no longer processes SubmitterListener.postSubmit(boolean) notification.

reprogrammer commented 13 years ago

@Wanderer777: As far as I remember, SubmitterListener.postSubmit(boolean) could have always been called without a preceding SubmitterListener.preSubmit() (See the class comment of SubmitterListener). We discussed the contract of SubmitterListener while working on issue #139.

reprogrammer commented 13 years ago

@Wanderer777: Why do you think that in the above scenario the main record would be deleted only after the uploading is over?

In CodingSpectator v1.0.0.201105300951, if an exception occurs in notifyPreSubmit. That is, if an exception occurs in the preSubmit of an implementer of SubmitterListener before calling the preSubmit of CodingTracker, codechanges.txt will be added to the SVN working but then deleted in the postSubmit of CodingTracker without getting uploaded, right?

Wanderer777 commented 13 years ago

@reprogrammer: If you take a look on the way we fixed issue #139 (please see the comment https://github.com/vazexqi/CodingSpectator/issues/139#issuecomment-750477 and the corresponding commit), you will notice that at that point (and in the preceding version as well) it was not possible to fail to deliver preSubmit and then deliver postSubmit, because any problem with delivering preSubmit would prevent the execution to reach the point, where it sends postSubmit. I think that if we study how the code of Submitter evolved, we could spot the point when the scenario that you described became possible (or in other words, when the expectations of the Submitter's client SafeRecorder were broken).

Wanderer777 commented 13 years ago

@reprogrammer: By "uploading is over" I meant that the execution of Submitter#submit is over rather than that a particular file was actually uploaded. The exception that happened for the participant says that a file was scheduled for addition but was missing, which means that the file existed when svnManager#doAdd() was called, but disappeared before svnManager#doCommit() performed its commit. And this would not happen if the file is deleted in postSubmit because postSubmit is sent as the last step of the uploading process (again, regardless of whether the actual upload happened or not). So, this scenario does not explain the problem that happened to the participant, but it demonstrates another severe problem, which has to be addressed anyway. I think that it is addressed in our new implementation of SafeRecorder (please see it in codingtracker branch).

reprogrammer commented 13 years ago

@Wanderer777: I agree with the following statement of your comment. Because notifyPostSubmit is inside a finally block, it is always the last step of the uploading process.

postSubmit is sent as the last step of the uploading process (again, regardless of whether the actual upload happened or not).

However, I'd like to discuss the following statement of the same comment with you:

So, this scenario does not explain the problem that happened to the participant.

Let's say the postSubmit of CodingTracker deletes codechanges.txt at the end of the first submission. My understanding of SaferRecorder in v1.0.0.201105300951 is that if CodingTracker doesn't write anything to codechanges.txt until the second submission, the second submission will fail at doCommit because of the missing codechanges.txt. On the other hand, if CodingTracker writes something to codechanges.txt until the second submission, the second submission may succeed. But, CodingTracker would have silently lost some data by that time.

reprogrammer commented 13 years ago

@Wanderer777: I extracted the following exception trace from the error log at cs-118/ff70331f-61ba-4985-867d-8d855147324b/1.0.0.201105300951/error.log:

!SESSION 2011-06-15 17:33:50.642 -----------------------------------------------
eclipse.buildId=M20110210-1200
java.version=1.6.0_20
java.vendor=Sun Microsystems Inc.
BootLoader constants: OS=linux, ARCH=x86, WS=gtk, NL=en_US
Command-line arguments:  -os linux -ws gtk -arch x86

!ENTRY edu.illinois.codingspectator.monitor.core.ui 4 0 2011-06-15 19:51:23.036
!MESSAGE Failed to upload CodingSpectator data.
!STACK 0
edu.illinois.codingspectator.monitor.ui.submission.Submitter$SubmissionException: org.tmatesoft.svn.core.SVNException: svn: Working copy '/path/to/workspace/.metadata/.plugins/edu.illinois.codingspectator.data/1.0.0.201105300951/eclipse-refactorings/.workspace/2011/6/23' locked; try performing 'cleanup'
    at edu.illinois.codingspectator.monitor.ui.submission.Submitter.submit(Submitter.java:101)
    at edu.illinois.codingspectator.monitor.ui.Uploader$1.run(Uploader.java:56)
    at org.eclipse.core.internal.jobs.Worker.run(Worker.java:54)
Caused by: org.tmatesoft.svn.core.SVNException: svn: Working copy '/path/to/workspace/.metadata/.plugins/edu.illinois.codingspectator.data/1.0.0.201105300951/eclipse-refactorings/.workspace/2011/6/23' locked; try performing 'cleanup'
    at org.tmatesoft.svn.core.internal.wc.SVNErrorManager.error(SVNErrorManager.java:64)
    at org.tmatesoft.svn.core.internal.wc.SVNErrorManager.error(SVNErrorManager.java:51)
    at org.tmatesoft.svn.core.internal.wc.admin.SVNAdminArea14.lock(SVNAdminArea14.java:1562)
    at org.tmatesoft.svn.core.internal.wc.admin.SVNWCAccess.doOpen(SVNWCAccess.java:370)
    at org.tmatesoft.svn.core.internal.wc.admin.SVNWCAccess.open(SVNWCAccess.java:274)
    at org.tmatesoft.svn.core.internal.wc.admin.SVNWCAccess.probeOpen(SVNWCAccess.java:301)
    at org.tmatesoft.svn.core.internal.wc.admin.SVNWCAccess.probeOpen(SVNWCAccess.java:286)
    at org.tmatesoft.svn.core.internal.wc.admin.SVNWCAccess.probeTry(SVNWCAccess.java:322)
    at org.tmatesoft.svn.core.internal.wc.SVNWCManager.add(SVNWCManager.java:79)
    at org.tmatesoft.svn.core.internal.wc.SVNWCManager.add(SVNWCManager.java:62)
    at org.tmatesoft.svn.core.wc.SVNWCClient.addDirectory(SVNWCClient.java:3103)
    at org.tmatesoft.svn.core.wc.SVNWCClient.addDirectory(SVNWCClient.java:3136)
    at org.tmatesoft.svn.core.wc.SVNWCClient.addDirectory(SVNWCClient.java:3136)
    at org.tmatesoft.svn.core.wc.SVNWCClient.addDirectory(SVNWCClient.java:3136)
    at org.tmatesoft.svn.core.wc.SVNWCClient.addDirectory(SVNWCClient.java:3136)
    at org.tmatesoft.svn.core.wc.SVNWCClient.addDirectory(SVNWCClient.java:3136)
    at org.tmatesoft.svn.core.wc.SVNWCClient.addDirectory(SVNWCClient.java:3136)
    at org.tmatesoft.svn.core.wc.SVNWCClient.doAdd(SVNWCClient.java:1761)
    at org.tmatesoft.svn.core.wc.SVNWCClient.doAdd(SVNWCClient.java:1574)
    at edu.illinois.codingspectator.monitor.core.submission.LocalSVNManager.doAdd(LocalSVNManager.java:74)
    at edu.illinois.codingspectator.monitor.core.submission.SVNManager.doAdd(SVNManager.java:41)
    at edu.illinois.codingspectator.monitor.ui.submission.Submitter.submit(Submitter.java:96)
    ... 2 more
!SESSION 2011-06-15 19:51:50.342 -----------------------------------------------
eclipse.buildId=M20110210-1200
java.version=1.6.0_20
java.vendor=Sun Microsystems Inc.
BootLoader constants: OS=linux, ARCH=x86, WS=gtk, NL=en_US
Command-line arguments:  -os linux -ws gtk -arch x86

!ENTRY edu.illinois.codingspectator.monitor.core.ui 4 0 2011-06-15 19:52:32.641
!MESSAGE Failed to upload CodingSpectator data.
!STACK 0
edu.illinois.codingspectator.monitor.ui.submission.Submitter$SubmissionException: org.tmatesoft.svn.core.SVNException: svn: Commit failed (details follow):
svn: '/path/to/workspace/.metadata/.plugins/edu.illinois.codingspectator.data/1.0.0.201105300951/refactorings/refactoring-problems.log' is scheduled for addition, but is missing
    at edu.illinois.codingspectator.monitor.ui.submission.Submitter.submit(Submitter.java:101)
    at edu.illinois.codingspectator.monitor.ui.Uploader$1.run(Uploader.java:56)
    at org.eclipse.core.internal.jobs.Worker.run(Worker.java:54)
Caused by: org.tmatesoft.svn.core.SVNException: svn: Commit failed (details follow):
svn: '/path/to/workspace/.metadata/.plugins/edu.illinois.codingspectator.data/1.0.0.201105300951/refactorings/refactoring-problems.log' is scheduled for addition, but is missing
    at org.tmatesoft.svn.core.internal.wc.SVNErrorManager.error(SVNErrorManager.java:85)
    at org.tmatesoft.svn.core.internal.wc.SVNErrorManager.error(SVNErrorManager.java:69)
    at org.tmatesoft.svn.core.wc.SVNCommitClient.doCollectCommitItems(SVNCommitClient.java:1236)
    at org.tmatesoft.svn.core.wc.SVNCommitClient.doCommit(SVNCommitClient.java:825)
    at edu.illinois.codingspectator.monitor.core.submission.RemoteSVNManager.doCommit(RemoteSVNManager.java:60)
    at edu.illinois.codingspectator.monitor.core.submission.SVNManager.doCommit(SVNManager.java:37)
    at edu.illinois.codingspectator.monitor.ui.submission.Submitter.submit(Submitter.java:98)
    ... 2 more
Caused by: org.tmatesoft.svn.core.SVNException: svn: '/path/to/workspace/.metadata/.plugins/edu.illinois.codingspectator.data/1.0.0.201105300951/refactorings/refactoring-problems.log' is scheduled for addition, but is missing
    at org.tmatesoft.svn.core.internal.wc.SVNErrorManager.error(SVNErrorManager.java:64)
    at org.tmatesoft.svn.core.internal.wc.SVNErrorManager.error(SVNErrorManager.java:51)
    at org.tmatesoft.svn.core.internal.wc.SVNCommitUtil.harvestCommitables(SVNCommitUtil.java:822)
    at org.tmatesoft.svn.core.internal.wc.SVNCommitUtil.harvestCommitables(SVNCommitUtil.java:983)
    at org.tmatesoft.svn.core.internal.wc.SVNCommitUtil.harvestCommitables(SVNCommitUtil.java:983)
    at org.tmatesoft.svn.core.internal.wc.SVNCommitUtil.harvestCommitables(SVNCommitUtil.java:983)
    at org.tmatesoft.svn.core.internal.wc.SVNCommitUtil.harvestCommitables(SVNCommitUtil.java:534)
    at org.tmatesoft.svn.core.wc.SVNCommitClient.doCollectCommitItems(SVNCommitClient.java:1208)
    ... 6 more
reprogrammer commented 13 years ago

@Wanderer777: You and I changed the contract of SubmitterListener together when we extracted the saferecorder plug-in in 6f2b13f3125a79d990f432c6cdd76b1cfb1864ac.

Wanderer777 commented 13 years ago

@reprogrammer: I am not sure about CodingSpectator v1.0.0.201105300951, but I performed this test in CodingSpectator v1.0.0.201107061725 (not sure if this was the official release or not though): I deleted a previously uploaded codechanges.txt and performed an upload. I did not get any errors, instead file codechanges.txt reappeared with the previously uploaded content. Considering that the version of the participant cs-509 was released 11 days later, I would assume that it has the same behavior, which confirms that the scenario suggested by you would not explain the error. At the same time, it might explain the error of the participant cs-118. To check that this is indeed so, we need to install v1.0.0.201105300951. Do you have an Eclipse with v1.0.0.201105300951 or know a way to install this older version?

Wanderer777 commented 13 years ago

@reprogrammer: I installed CodingSpectator v1.0.0.201105300951 and repeated the above scenario (i.e. uploaded a file, then deleted it and started the upload again) and observed the same result: no errors/warnings and the file was restored to the previously uploaded content. So, at the moment, we do not have an explanation neither for cs-118 nor for cs-509.

reprogrammer commented 13 years ago

@Wanderer777: How does the file get restored to the previously uploaded content? What triggers the restoration?

reprogrammer commented 13 years ago

@Wanderer777: Could you search the source code for all places where CodingSpectator or CodingTracker delete a file? I suggest to search for keywords such as "delete" and "remove". Let's see if we can find any other places that may unexpectedly delete a log file.

Wanderer777 commented 13 years ago

@reprogrammer: According to the workspace data uploaded by the participant cs-509, file codechages.txt was never uploaded (i.e. there is no .svn folder for it), but actually it was uploaded since we have it in our repository. This means that the participant reverted his workspace to the state before the first upload of this file. This confirms my assumption that the error that this participant observed has nothing to do with the way SafeRecorder works.

Wanderer777 commented 13 years ago

@reprogrammer:

  1. I do not know what mechanism causes file restoration. It might be related to the way SVNKit handles SVN operations on a file. Considering that you implemented the code that interacts with SVNKit, you might be more knowledgeable in this matter.
  2. Conceptually, SafeRecorder is a centralized place to work with log files and no other code can access or manipulate record files directly. I looked for other places in CodingSpectator that delete files and found a couple of them (this list does not include tests and operation replaying): edu.illinois.codingspectator.efs.EFSFile#delete(); edu.illinois.codingspectator.file.utils.FileUtils#createFile(String); edu.illinois.codingspectator.mergehistories.DataReader#createFile(String); edu.illinois.codingspectator.refactorings.parser.RefactoringLog#delete(). These codes are related to handling EFS files and consolidating refactoring histories (and I did not find any references to the last method), so these methods can not explain the absence of a SafeRecorder log file.
reprogrammer commented 13 years ago

@Wanderer777: I expect SVNKit to be consistent with the behavior of the SVN command line client. Can you simulate the restoration with the SVN command line client?

Wanderer777 commented 13 years ago

@reprogrammer: I am not sure I understand why we need to explore the ability of SVNKit to restore deleted log files as part of this issue. We already found an explanation for the problem of the participant cs-509 (which would also explain the case of the participant cs-118). Also, we found another potential problem with SafeRecorder. Both these problems will be resolved in the new version of SafeRecorder, so this issue can be closed.

reprogrammer commented 13 years ago

@Wanderer777: Simply, I didn't expect a deleted file to be restored. I don't have an explanation for this phenomenon. I'm not sure if it's a bug or a feature. I don't know the repercussion of this behavior. Is it a safe behavior or could lead to other bugs in some scenarios? I think it's important to investigate how a deleted file gets restored. It's probably not related to this issue. So, as you suggested, you could close this issue and open a new one for unexpected restorations.

Wanderer777 commented 13 years ago

@reprogrammer: I do not think that this behavior is problematic for us. Manually deleting a file from the watched directory is a severe intrusion into the work of CodignSpectator, which alone would justify its failure. But due to files restoration that we noticed, CodingSpectator would not fail and continue to upload data properly, which is a better than expected outcome for such an intrusion from a participant. Anyway, I opened issue #306, which is dedicated to this behavior in case we would like to investigate it further and document our findings as part this issue.