Some Eclipse Foundation services are deprecated, or will be soon. Please ensure you've read this important communication.

Bug 345069

Summary: starting virgo from eclipse may produce "Destination path already exists" error
Product: [RT] Virgo Reporter: Pachara Tinamas <mrpachara>
Component: runtimeAssignee: Borislav Kapukaranov <b.kapukaranov>
Status: CLOSED WORKSFORME QA Contact:
Severity: normal    
Priority: P3 CC: b.kapukaranov, glyn.normington, hsiliev
Version: unspecified   
Target Milestone: ---   
Hardware: PC   
OS: Windows 7   
Whiteboard:
Attachments:
Description Flags
error log none

Description Pachara Tinamas CLA 2011-05-08 04:50:47 EDT
Build Identifier: 20110301-1815

starting virgo from eclipse may cast "Destination path already exists" error.
The full error is :

[2011-05-08 15:27:26.289] startup-tracker              <KE0001I> Kernel starting. 
[2011-05-08 15:27:34.904] service-monitor-thread-1     <KE0100W> Reference '&objectNameCreator' in bundle 'org.eclipse.virgo.kernel.shell' version '2.1.1.RELEASE' is waiting for service with filter '(objectClass=org.eclipse.virgo.kernel.model.management.RuntimeArtifactModelObjectNameCreator)'. 
[2011-05-08 15:27:36.319] Thread-6                     <KE0101I> Reference '&objectNameCreator' in bundle 'org.eclipse.virgo.kernel.shell' version '2.1.1.RELEASE' was satisfied by service with filter '(objectClass=org.eclipse.virgo.kernel.model.management.RuntimeArtifactModelObjectNameCreator)'. 
[2011-05-08 15:27:36.779] startup-tracker              <KE0002I> Kernel started. 
[2011-05-08 15:27:37.020] system-artifacts             <DE0000I> Installing plan 'org.eclipse.virgo.kernel.userregion.springdm' version '2.1.1'. 
[2011-05-08 15:27:46.356] system-artifacts             <ME0003I> Dump 'serviceability\dump\2011-05-08-15-27-333' generated 
[2011-05-08 15:27:46.368] system-artifacts             <DE0002E> Installation of plan 'org.eclipse.virgo.kernel.userregion.springdm' version '2.1.1' failed. org.eclipse.virgo.util.io.FatalIOException: Cannot move path 'D:\mrPachara\Applications\virgo-web-server-2.1.1.RELEASE\work\org.eclipse.virgo.kernel.deployer_2.1.1.RELEASE\staging\global\bundle\org.springframework.osgi.core\1.2.1\org.springframework.osgi.core-1.2.1.jar' to 'D:\mrPachara\Applications\virgo-web-server-2.1.1.RELEASE\work\org.eclipse.virgo.kernel.deployer_2.1.1.RELEASE\staging\global\bundle\org.springframework.osgi.core\1.2.1\org.springframework.osgi.core-1.2.1.jar-past'. Destination path already exists.
	at org.eclipse.virgo.util.io.PathReference.moveTo(PathReference.java:304)
	at org.eclipse.virgo.kernel.install.artifact.internal.StandardArtifactStorage.stashContent(StandardArtifactStorage.java:113)
	at org.eclipse.virgo.kernel.install.artifact.internal.StandardArtifactStorage.synchronize(StandardArtifactStorage.java:82)
	at org.eclipse.virgo.kernel.install.artifact.internal.StandardArtifactStorage.synchronize(StandardArtifactStorage.java:59)
	at org.eclipse.virgo.kernel.install.artifact.internal.StandardArtifactStorage.<init>(StandardArtifactStorage.java:54)
	at org.eclipse.virgo.kernel.install.artifact.internal.StandardArtifactStorageFactory.create(StandardArtifactStorageFactory.java:54)
	at org.eclipse.virgo.kernel.install.artifact.internal.StandardInstallArtifactTreeInclosure.createInstallTree(StandardInstallArtifactTreeInclosure.java:102)
	at org.eclipse.virgo.kernel.deployer.core.internal.PlanResolver.createInstallArtifactTree(PlanResolver.java:113)
	at org.eclipse.virgo.kernel.deployer.core.internal.PlanResolver.operate(PlanResolver.java:70)
	at org.eclipse.virgo.kernel.deployer.core.internal.PlanResolver.access$0(PlanResolver.java:62)
	at org.eclipse.virgo.kernel.deployer.core.internal.PlanResolver$1.visit(PlanResolver.java:56)
	at org.eclipse.virgo.util.common.ThreadSafeArrayListTree.visit(ThreadSafeArrayListTree.java:165)
	at org.eclipse.virgo.kernel.deployer.core.internal.PlanResolver.transform(PlanResolver.java:53)
	at org.eclipse.virgo.kernel.install.pipeline.stage.transform.internal.TransformationStage.doProcessTree(TransformationStage.java:55)
	at org.eclipse.virgo.kernel.install.pipeline.stage.AbstractPipelineStage.process(AbstractPipelineStage.java:41)
	at org.eclipse.virgo.kernel.install.pipeline.internal.StandardPipeline.doProcessTree(StandardPipeline.java:62)
	at org.eclipse.virgo.kernel.install.pipeline.internal.CompensatingPipeline.doProcessTree(CompensatingPipeline.java:72)
	at org.eclipse.virgo.kernel.install.pipeline.stage.AbstractPipelineStage.process(AbstractPipelineStage.java:41)
	at org.eclipse.virgo.kernel.install.pipeline.internal.StandardPipeline.doProcessTree(StandardPipeline.java:62)
	at org.eclipse.virgo.kernel.install.pipeline.stage.AbstractPipelineStage.process(AbstractPipelineStage.java:41)
	at org.eclipse.virgo.kernel.deployer.core.internal.PipelinedApplicationDeployer.driveInstallPipeline(PipelinedApplicationDeployer.java:271)
	at org.eclipse.virgo.kernel.deployer.core.internal.PipelinedApplicationDeployer.doInstall(PipelinedApplicationDeployer.java:151)
	at org.eclipse.virgo.kernel.deployer.core.internal.PipelinedApplicationDeployer.install(PipelinedApplicationDeployer.java:123)
	at org.eclipse.virgo.kernel.deployer.core.internal.PipelinedApplicationDeployer.deploy(PipelinedApplicationDeployer.java:190)
	at org.eclipse.virgo.kernel.userregion.internal.InitialArtifactDeployer$ArtifactDeployingRunnable.deployArtifacts(InitialArtifactDeployer.java:155)
	at org.eclipse.virgo.kernel.userregion.internal.InitialArtifactDeployer$ArtifactDeployingRunnable.run(InitialArtifactDeployer.java:145)
	at java.lang.Thread.run(Thread.java:662)

[2011-05-08 15:27:46.377] system-artifacts             <DE0003E> Install failed for plan 'org.eclipse.virgo.kernel.userregion.springdm' version '2.1.1'. 


--------------------------------
my fixed is start virgo from command line with -clean option and stop it, then it can start virgo from eclipse again.

Reproducible: Sometimes

Steps to Reproduce:
1. to start virgo from eclipse
Comment 1 Pachara Tinamas CLA 2011-05-08 04:52:59 EDT
Created attachment 195018 [details]
error log
Comment 2 Glyn Normington CLA 2011-05-09 06:47:36 EDT
Thanks for raising this.
Comment 3 Borislav Kapukaranov CLA 2011-05-17 02:49:32 EDT
I tried 15 restarts from Eclipse and some stops+starts and it didn't reproduce with Virgo 2.1.1 on my Win7 machine. 

What is interesting here is that the destination path is always deleted before trying to perform movement, as can be seen here:

    private void stashContent() {
        if (this.baseStagingPathReference.exists()) {
            this.pastStagingPathReference.delete(true);
            this.baseStagingPathReference.moveTo(this.pastStagingPathReference);
        }
    }

The call is performed in a single thread, so unless the windows FS returns and starts deleting separately I can't explain what's going on. 
But it clearly sounds like a racing issue:
1. we call delete, the deletion is probably triggered
2. when we start moving the file is still not deleted, therefore the exception

Pachara, I'm curious when the problem occurs once, after that does it always reproduce? Cause it sounds like it shouldn't be always reproducible after the first time.
I tried that by stopping the startup with the debugger and when the pastDestination was deleted i created a new file for it. The server failed as described here but when i restarted it was fine again.

I don't see what we can do apart from adding a small timeout to allow any FS to complete the operation.
One thing you can try is optimizing the FS operations on your machine.

Is the issue occuring often?
Comment 4 Borislav Kapukaranov CLA 2011-05-17 02:52:27 EDT
Also i'm ruling out the long paths Win issue as the destination in this case is less than 220 characters long.
Comment 5 Hristo Iliev CLA 2011-05-17 03:06:31 EDT
The delete may return without actually removing the file if Windows decides to perform "delayed write".

This may be the issue here - a file is not deleted, when the next Virgo startup is triggered.
Comment 6 Borislav Kapukaranov CLA 2011-05-17 03:16:22 EDT
There is a try to delete the file at Virgo's startup - it is intentionally left there. The idea is to delete it only when there is an update to that bundle, so that the "past" version gets updated.

Again, there isn't much we can do about this.

Pachara you can try this hint: 
http://www.pcmag.com/article2/0,2817,1819756,00.asp  on how to disable the "delayed write" and get back to us if it helps.
Comment 7 Pachara Tinamas CLA 2011-05-18 05:20:44 EDT
I will try it.

Thank You.
Comment 8 Glyn Normington CLA 2011-05-25 10:34:45 EDT
Hi Pachara

Did you get a chance to try it? It would be good to be able to progress this bug.

Thanks,
Glyn
Comment 9 Glyn Normington CLA 2011-05-27 04:15:11 EDT
Closing as "cannot reproduce". Please re-open if the suggested workaround does not provide a solution.