This Bugzilla instance is a read-only archive of historic NetBeans bug reports. To report a bug in NetBeans please follow the project's instructions for reporting issues.

Bug 257565 - FileAlreadyLockedException: /home/vk/.../fs_server/nbproject/private/timestamps-svarog-vkvashin-22
Summary: FileAlreadyLockedException: /home/vk/.../fs_server/nbproject/private/timestam...
Status: VERIFIED FIXED
Alias: None
Product: cnd
Classification: Unclassified
Component: Remote (show other bugs)
Version: 8.1
Hardware: All All
: P3 normal (vote)
Assignee: Vladimir Kvashin
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2016-01-14 14:11 UTC by Vladimir Kvashin
Modified: 2016-02-03 14:03 UTC (History)
0 users

See Also:
Issue Type: DEFECT
Exception Reporter:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Vladimir Kvashin 2016-01-14 14:11:19 UTC
This corresponds to exception report 175548 (http://statistics.netbeans.org/analytics/detail.do?id=175548). 

However I see this as a bug in remote.

I built a small remote project via auto-copy.
At some moment rfs_controller was killed externally.
But I guess the same can happen just occasionally, this is an obvious synchronization issue.

org.openide.filesystems.FileAlreadyLockedException: /home/vk/testcode/misc/fs_server_w_release_bin/tools/fs_server/nbproject/private/timestamps-svarog-vk-22
        at org.netbeans.modules.masterfs.filebasedfs.fileobjects.LockForFile.registerLock(LockForFile.java:115)
        at org.netbeans.modules.masterfs.filebasedfs.fileobjects.LockForFile.tryLock(LockForFile.java:104)
        at org.netbeans.modules.masterfs.filebasedfs.fileobjects.FileObj.lock(FileObj.java:409)
        at org.openide.filesystems.FileObject.getOutputStream(FileObject.java:812)
        at org.netbeans.modules.cnd.remote.sync.FileData.store(FileData.java:202)
        at org.netbeans.modules.cnd.remote.sync.RfsLocalController.shutdown(RfsLocalController.java:247)
        at org.netbeans.modules.cnd.remote.sync.RfsLocalController.runImpl(RfsLocalController.java:239)
        at org.netbeans.modules.cnd.utils.NamedRunnable.run(NamedRunnable.java:62)
        at org.openide.util.RequestProcessor$Task.run(RequestProcessor.java:1443)
        at org.netbeans.modules.openide.util.GlobalLookup.execute(GlobalLookup.java:68)
        at org.openide.util.lookup.Lookups.executeWith(Lookups.java:303)
        at org.openide.util.RequestProcessor$Processor.run(RequestProcessor.java:2058)
java.lang.Throwable: Locked by:
        at org.openide.filesystems.FileLock.<init>(FileLock.java:88)
        at org.netbeans.modules.masterfs.filebasedfs.fileobjects.LockForFile.<init>(LockForFile.java:92)
        at org.netbeans.modules.masterfs.filebasedfs.fileobjects.LockForFile.tryLock(LockForFile.java:103)
        at org.netbeans.modules.masterfs.filebasedfs.fileobjects.FileObj.lock(FileObj.java:409)
        at org.openide.filesystems.FileObject.getOutputStream(FileObject.java:812)
        at org.netbeans.modules.cnd.remote.sync.FileData.store(FileData.java:202)
        at org.netbeans.modules.cnd.remote.sync.RfsLocalController.shutdown(RfsLocalController.java:247)
        at org.netbeans.modules.cnd.remote.sync.RfsLocalController.runImpl(RfsLocalController.java:239)
        at org.netbeans.modules.cnd.utils.NamedRunnable.run(NamedRunnable.java:62)
        at org.openide.util.RequestProcessor$Task.run(RequestProcessor.java:1443)
        at org.netbeans.modules.openide.util.GlobalLookup.execute(GlobalLookup.java:68)
        at org.openide.util.lookup.Lookups.executeWith(Lookups.java:303)
        at org.openide.util.RequestProcessor$Processor.run(RequestProcessor.java:2058)
Comment 1 Vladimir Kvashin 2016-01-15 17:07:22 UTC
I'm not sure I know safe and easy to fix this in the patch right now.
Here is my investigation.

I see 2 problems here.

1). Very simple. 
Access to o.n.m.cnd.remote.sync.FileData.store is not synchronized, 
i. e. several threads can try simultaneously open one and the same file for writing. (Please note that instances of RfsLocalController differ in two stacks above)

2) More complex one that concerns RfsSyncWorker init & shutdown and RfsLocalController synhronization. Here are some details.

I see two subproblems here.

First a few words on how RemoteSyncWorker behave.
It has two methods, init and shutdown. 
The init() method is called before delegate action handler (i. e. real build) is called.
The shutdown() method is called in reaction to executionFinished for build.
So init() and shutdown() are called from different threads, but it is guaranteed that shutdown() is called after the real build finished.

A) Lack of RfsLocalController synhronization with RfsSyncWorker init & shutdown.

RfsLocalController runs in its own thread (it contains a loop that reads requests and sends responses).
It is posted into a static multytask RP from RemoteSyncWorker.startup
at org.netbeans.modules.cnd.remote.sync.RfsSyncWorker.startupImpl(RfsSyncWorker.java:207)
  at org.netbeans.modules.cnd.remote.sync.RfsSyncWorker.startup(RfsSyncWorker.java:130)
  at org.netbeans.modules.cnd.remote.sync.RemoteBuildProjectActionHandler.execute(RemoteBuildProjectActionHandler.java:176)
  at org.netbeans.modules.cnd.makeproject.api.ProjectActionSupport$EventsProcessor.run(ProjectActionSupport.java:598)
It finishes when the rfs_controller process finishes (process stdout reader returs null).
The rfs_controller process finishes when it is killed by RemoteProcessController.stop
  at RfsSyncWorker.remoteControllerCleanup()
  at RfsSyncWorker.shutdown()
  at RemoteBuildProjectActionHandler in reaction to executionFinished for build.
The RfsLocalController.shutdown method (which writes to the file) is called after the cycle is over.

So the RfsLocalController.shutdown is ran in a separate thread, if you set breakpoint in the beginning, nothing prevents project from starting another build action on the same project.

Possible fix: RfsSyncWorker.shutdown waits until RfsSyncWorker.shutdown() is completed.


B) Lack of synhronization between RfsSyncWorker.init & RfsSyncWorker.shutdown (sic!)

Since RfsSyncWorker.init & RfsSyncWorker.shutdown are performed in different threads, we can get two stacks in unpredictable order:

For the previous build (usually "clean"):
"org.netbeans.api.extexecution.base.BaseExecutionService"
  at org.netbeans.modules.cnd.remote.sync.RfsSyncWorker.shutdown(RfsSyncWorker.java:269)
  at org.netbeans.modules.cnd.remote.sync.RemoteBuildProjectActionHandler$1.executionFinished(RemoteBuildProjectActionHandler.java:183)
  at org.netbeans.modules.cnd.makeproject.api.DefaultProjectActionHandler$1.executionFinished(DefaultProjectActionHandler.java:139)
  at org.netbeans.modules.cnd.makeproject.api.DefaultProjectActionHandler$ProcessChangeListener.run(DefaultProjectActionHandler.java:531)
  at org.netbeans.modules.nativeexecution.api.execution.NativeExecutionService$PostRunnable.run(NativeExecutionService.java:423)
  at org.netbeans.api.extexecution.ExecutionService$4.run(ExecutionService.java:229)
  at org.netbeans.api.extexecution.ExecutionService$4.run(ExecutionService.java:221)
  at org.netbeans.api.extexecution.base.BaseExecutionService$2.call(BaseExecutionService.java:299)
  ...
And for the next build(usually "build"):
"ProjectActionSupport.tasks"
  at org.netbeans.modules.cnd.remote.sync.RfsSyncWorker.startupImpl(RfsSyncWorker.java:207)
  at org.netbeans.modules.cnd.remote.sync.RfsSyncWorker.startup(RfsSyncWorker.java:130)
  at org.netbeans.modules.cnd.remote.sync.RemoteBuildProjectActionHandler.execute(RemoteBuildProjectActionHandler.java:176)
  at org.netbeans.modules.cnd.makeproject.api.ProjectActionSupport$EventsProcessor.run(ProjectActionSupport.java:598)
  at org.openide.util.RequestProcessor$Task.run(RequestProcessor.java:1443)
  at org.openide.util.RequestProcessor$Processor.run(RequestProcessor.java:2058)
  ...

  If I resume the 2-nd thread, but not the 1-st, then I eventually get to the RfsSyncWorker.shutdown (1-st thread) for the same project.

One reason for (B) to occur is as follows:
ProjectActionSupport.EventsProcessor.run method sets it own ExecutionListener and waits for a latch (final CountDownLatch eventProcessed) that has its countDown() method called from executionFinished().

But remote action handler calls its shutdown in executionFinished either, and its listener fired after the one above. I made an experiment that proved that: reversed the order of listeners. After that each new startup occurred only after previous shutdown is done.
Comment 2 Vladimir Kvashin 2016-01-17 12:15:57 UTC
fixed on enum
07032f524290
Comment 3 ilia 2016-01-27 14:45:24 UTC
  Fixes of this bug:
    http://hg.netbeans.org/releases/rev/07032f524290
Comment 4 Alexander Pepin 2016-02-03 14:03:41 UTC
The bug is not reproducible in build 20160130.