Hi,
The following describes my situation:
1. I have a long running JVM process (p1).
2. The long running process instantiate another JVM process (p2).
3. On every instantiation of p2, p1 prepares an instance of FileHandler for
p2
(used through a redirect thread of logging) as:
new FileHandler("/path/to/log/app.stdouterr.%u.%g.log"
4. p2 is short-lived and on its JVM exit, it closes FileHandler
5. p1 can start p2 an arbitrary number of times
Our observation started with the following exception:
Caused by: java.io.IOException: Couldn't get lock for
/path/to/log/app.stdouterr.%u.%g.log
at java.util.logging.FileHandler.openFiles(FileHandler.java:422)
at java.util.logging.FileHandler.<init>(FileHandler.java:318)
(...)
Then, I tried to understand why, and I used the following on the running
server:
$ lsof -uappuser | grep -E "\/path\/to\/log"
It's interesting that I see 100 files as ".lck" in generation 0
as the following shows (the results are trimmed):
===
java 14515 appuser 182wW REG 252,0 0 109052248
/path/to/log/app.stdouterr.0.0.log.lck (deleted)
java 14515 appuser 183wW REG 252,0 0 92274968
/path/to/log/app.stdouterr.1.0.log.lck (deleted)
java 14515 appuser 184wW REG 252,0 0 125829396
/path/to/log/app.stdouterr.2.0.log.lck (deleted)
.
.
.
java 14515 appuser 206wW REG 252,0 0 109052253
/path/to/log/app.stdouterr.98.0.log.lck (deleted)
java 14515 appuser 207wW REG 252,0 0 125829401
/path/to/log/app.stdouterr.99.0.log.lck (deleted)
java 14515 appuser 168wW REG 252,0 0 8388893
/path/to/log/app.stdouterr.100.0.log.lck
java 14515 appuser 176w REG 252,0 367 8388894
/path/to/log/app.stdouterr.100.0.log
===
Please note that except the last two, all the *.lck files are marked as
(deleted),
which means they are not available in the file system (confirmed)
but a process has an open handle on the path.
Simply, based on (3) and (4), when p1 would reach the 100th time it wants
to
instantiate p2, we start to observe the exception.
As far as I can see the source for FileHandler:
- a static field is used to hold the lock files
- in our setup, the JVM in p1 initiates the above static field as part of
the first time preparing p2
- the (deleted) in the above, means that FileHandler#close has been called
with success.
Questions/Suggestions:
(a) The above (deleted) handles would not be released until p1 JVM goes
down, correct?
(b) If (a) is correct, is there way to ask JVM to do so on FileHandler? If
yes, where should I look into?
(c) If (b) is no, is there a chance FileHandler could introduce a new API
method to be able to perform such clean-up without having to exit p1 JVM?
Thanks,
Behrooz
