Logging FileHandler: static locks and hardcoded maximum number

[Daniel Fuchs]

Hi Behrooz,

I have made several fixes WRT to lock files used by FileHandler
recently. Could you please tell us which version of java you
are using when observing this?

I'll need to analyze your issue a bit deeper - and knowing
the version (java -version) will help me in not making false
assumptions :-)

I'm not sure I understand the notion of 'preparing a FileHandler
for p2' - p1 will need to close that file handler before p2 starts,
otherwise the file that p1 uses will be locked, and p2 will have
to create a new file.

best regards,

-- daniel

On 19/02/15 12:44, Behrooz Nobakht wrote:
> 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
>